- Fix #545: improved logging, the ip address of the error is printed

  on the same log-line as the error.

git-svn-id: file:///svn/unbound/trunk@3112 be551aaa-1e26-0410-a405-d3ace91eadb9

diff --git a/doc/Changelog b/doc/Changelog
index e4f20f3a9deb821c868c1050433f8936bfa9e8ca..9bda05fbc72a3f443681c68767df99e486cd5c4f 100644 (file)
--- a/doc/Changelog
+++ b/doc/Changelog
@@ -12,6 +12,8 @@
          64bit systems.
        - Fix #558: failed prefetch lookup does not remove cached response
          but delays next prefetch (in lieu of caching a SERVFAIL).
+       - Fix #545: improved logging, the ip address of the error is printed
+         on the same log-line as the error.
 
 8 April 2014: Wouter
        - Fix #574: make test fails on Ubuntu 14.04.  Disabled remote-control

diff --git a/services/listen_dnsport.c b/services/listen_dnsport.c
index 49059f83af9829b46900cf459584d08de1820550..badd303d9e292549ac93702cf7b68f232a208665 100644 (file)
--- a/services/listen_dnsport.c
+++ b/services/listen_dnsport.c
@@ -419,8 +419,7 @@ create_udp_sock(int family, int socktype, struct sockaddr* addr,
                if(family==AF_INET6 && errno==EINVAL)
                        *noproto = 1;
                else if(errno != EADDRINUSE) {
-                       log_err("can't bind socket: %s", strerror(errno));
-                       log_addr(0, "failed address",
+                       log_err_addr("can't bind socket", strerror(errno),
                                (struct sockaddr_storage*)addr, addrlen);
                }
 #endif /* EADDRINUSE */
@@ -428,9 +427,8 @@ create_udp_sock(int family, int socktype, struct sockaddr* addr,
 #else /* USE_WINSOCK */
                if(WSAGetLastError() != WSAEADDRINUSE &&
                        WSAGetLastError() != WSAEADDRNOTAVAIL) {
-                       log_err("can't bind socket: %s", 
-                               wsa_strerror(WSAGetLastError()));
-                       log_addr(0, "failed address",
+                       log_err_addr("can't bind socket", 
+                               wsa_strerror(WSAGetLastError()),
                                (struct sockaddr_storage*)addr, addrlen);
                }
                closesocket(s);
@@ -538,16 +536,14 @@ create_tcp_accept_sock(struct addrinfo *addr, int v6only, int* noproto,
                if(addr->ai_family==AF_INET6 && errno==EINVAL)
                        *noproto = 1;
                else {
-                       log_err("can't bind socket: %s", strerror(errno));
-                       log_addr(0, "failed address",
+                       log_err_addr("can't bind socket", strerror(errno),
                                (struct sockaddr_storage*)addr->ai_addr,
                                addr->ai_addrlen);
                }
                close(s);
 #else
-               log_err("can't bind socket: %s", 
-                       wsa_strerror(WSAGetLastError()));
-               log_addr(0, "failed address",
+               log_err_addr("can't bind socket", 
+                       wsa_strerror(WSAGetLastError()),
                        (struct sockaddr_storage*)addr->ai_addr,
                        addr->ai_addrlen);
                closesocket(s);

diff --git a/services/outside_network.c b/services/outside_network.c
index 3b685804f0de5ca9bebe6252ed1e0a51a3eb3583..4baa1080d2371f9a2e1059db8d771f513e8a086f 100644 (file)
--- a/services/outside_network.c
+++ b/services/outside_network.c
@@ -210,12 +210,12 @@ outnet_tcp_take_into_use(struct waiting_tcp* w, uint8_t* pkt, size_t pkt_len)
                s = socket(PF_INET, SOCK_STREAM, IPPROTO_TCP);
        if(s == -1) {
 #ifndef USE_WINSOCK
-               log_err("outgoing tcp: socket: %s", strerror(errno));
+               log_err_addr("outgoing tcp: socket", strerror(errno),
+                       &w->addr, w->addrlen);
 #else
-               log_err("outgoing tcp: socket: %s", 
-                       wsa_strerror(WSAGetLastError()));
+               log_err_addr("outgoing tcp: socket", 
+                       wsa_strerror(WSAGetLastError()), &w->addr, w->addrlen);
 #endif
-               log_addr(0, "failed address", &w->addr, w->addrlen);
                return 0;
        }
        if(!pick_outgoing_tcp(w, s))
@@ -231,15 +231,14 @@ outnet_tcp_take_into_use(struct waiting_tcp* w, uint8_t* pkt, size_t pkt_len)
 #endif
                        if(tcp_connect_errno_needs_log(
                                (struct sockaddr*)&w->addr, w->addrlen))
-                               log_err("outgoing tcp: connect: %s",
-                                       strerror(errno));
+                               log_err_addr("outgoing tcp: connect",
+                                       strerror(errno), &w->addr, w->addrlen);
                        close(s);
 #else /* USE_WINSOCK */
                if(WSAGetLastError() != WSAEINPROGRESS &&
                        WSAGetLastError() != WSAEWOULDBLOCK) {
                        closesocket(s);
 #endif
-                       log_addr(0, "failed address", &w->addr, w->addrlen);
                        return 0;
                }
        }

diff --git a/smallapp/unbound-control.c b/smallapp/unbound-control.c
index 067e133fc16d9553d231e400ff394059a3804346..76de1b2d37e1054c6e7868d8b1f503327d0ce4ff 100644 (file)
--- a/smallapp/unbound-control.c
+++ b/smallapp/unbound-control.c
@@ -200,15 +200,14 @@ contact_server(const char* svr, struct config_file* cfg, int statuscmd)
 #endif
        }
        if(connect(fd, (struct sockaddr*)&addr, addrlen) < 0) {
-               log_addr(0, "address", &addr, addrlen);
 #ifndef USE_WINSOCK
-               log_err("connect: %s", strerror(errno));
+               log_err_addr("connect", strerror(errno), &addr, addrlen);
                if(errno == ECONNREFUSED && statuscmd) {
                        printf("unbound is stopped\n");
                        exit(3);
                }
 #else
-               log_err("connect: %s", wsa_strerror(WSAGetLastError()));
+               log_err_addr("connect", wsa_strerror(WSAGetLastError()), &addr, addrlen);
                if(WSAGetLastError() == WSAECONNREFUSED && statuscmd) {
                        printf("unbound is stopped\n");
                        exit(3);

diff --git a/util/net_help.c b/util/net_help.c
index 7f6daab4a1b4c9c82842527dd04b19174351d9c1..30d543e00197f5cb8001587524657509d88bbe97 100644 (file)
--- a/util/net_help.c
+++ b/util/net_help.c
@@ -329,6 +329,26 @@ void log_name_addr(enum verbosity_value v, const char* str, uint8_t* zone,
                        str, namebuf, family, dest, (int)port);
 }
 
+void log_err_addr(const char* str, const char* err,
+       struct sockaddr_storage* addr, socklen_t addrlen)
+{
+       uint16_t port;
+       char dest[100];
+       int af = (int)((struct sockaddr_in*)addr)->sin_family;
+       void* sinaddr = &((struct sockaddr_in*)addr)->sin_addr;
+       if(af == AF_INET6)
+               sinaddr = &((struct sockaddr_in6*)addr)->sin6_addr;
+       if(inet_ntop(af, sinaddr, dest, (socklen_t)sizeof(dest)) == 0) {
+               (void)strlcpy(dest, "(inet_ntop error)", sizeof(dest));
+       }
+       dest[sizeof(dest)-1] = 0;
+       port = ntohs(((struct sockaddr_in*)addr)->sin_port);
+       if(verbosity >= 4)
+               log_err("%s: %s for %s port %d (len %d)", str, err, dest,
+                       (int)port, (int)addrlen);
+       else    log_err("%s: %s for %s", str, err, dest);
+}
+
 int
 sockaddr_cmp(struct sockaddr_storage* addr1, socklen_t len1, 
        struct sockaddr_storage* addr2, socklen_t len2)

diff --git a/util/net_help.h b/util/net_help.h
index b92dd40e85d9bc630fbf604fbc3f2d847fc10742..54f4c9c0e7cd019fdf6045f08ede2b9dfc7a4771 100644 (file)
--- a/util/net_help.h
+++ b/util/net_help.h
@@ -156,6 +156,16 @@ void log_addr(enum verbosity_value v, const char* str,
 void log_name_addr(enum verbosity_value v, const char* str, uint8_t* zone, 
        struct sockaddr_storage* addr, socklen_t addrlen);
 
+/**
+ * Log errno and addr.
+ * @param str: descriptive string printed with it.
+ * @param err: errno string to print, i.e. strerror(errno).
+ * @param addr: the sockaddr to print. Can be ip4 or ip6.
+ * @param addrlen: length of addr.
+ */
+void log_err_addr(const char* str, const char* err,
+       struct sockaddr_storage* addr, socklen_t addrlen);
+
 /**
  * Convert address string, with "@port" appendix, to sockaddr.
  * Uses DNS port by default.

diff --git a/util/netevent.c b/util/netevent.c
index 189aaa4e4ea009e51aebad33afeb38140501a356..421d1a1bdacab624665205ab9ba6a9ddae0999d7 100644 (file)
--- a/util/netevent.c
+++ b/util/netevent.c
@@ -785,7 +785,7 @@ int comm_point_perform_accept(struct comm_point* c,
                        return -1;
                }
 #endif
-               log_err("accept failed: %s", strerror(errno));
+               log_err_addr("accept failed", strerror(errno), addr, *addrlen);
 #else /* USE_WINSOCK */
                if(WSAGetLastError() == WSAEINPROGRESS ||
                        WSAGetLastError() == WSAECONNRESET)
@@ -794,9 +794,9 @@ int comm_point_perform_accept(struct comm_point* c,
                        winsock_tcp_wouldblock(&c->ev->ev, EV_READ);
                        return -1;
                }
-               log_err("accept failed: %s", wsa_strerror(WSAGetLastError()));
+               log_err_addr("accept failed", wsa_strerror(WSAGetLastError()),
+                       addr, *addrlen);
 #endif
-               log_addr(0, "remote address is", addr, *addrlen);
                return -1;
        }
        fd_set_nonblock(new_fd);
@@ -1218,7 +1218,8 @@ comm_point_tcp_handle_read(int fd, struct comm_point* c, int short_ok)
                        if(errno == ECONNRESET && verbosity < 2)
                                return 0; /* silence reset by peer */
 #endif
-                       log_err("read (in tcp s): %s", strerror(errno));
+                       log_err_addr("read (in tcp s)", strerror(errno),
+                               &c->repinfo.addr, c->repinfo.addrlen);
 #else /* USE_WINSOCK */
                        if(WSAGetLastError() == WSAECONNRESET)
                                return 0;
@@ -1228,11 +1229,10 @@ comm_point_tcp_handle_read(int fd, struct comm_point* c, int short_ok)
                                winsock_tcp_wouldblock(&c->ev->ev, EV_READ);
                                return 1;
                        }
-                       log_err("read (in tcp s): %s", 
-                               wsa_strerror(WSAGetLastError()));
+                       log_err_addr("read (in tcp s)", 
+                               wsa_strerror(WSAGetLastError()),
+                               &c->repinfo.addr, c->repinfo.addrlen);
 #endif
-                       log_addr(0, "remote address is", &c->repinfo.addr,
-                               c->repinfo.addrlen);
                        return 0;
                } 
                c->tcp_byte_count += r;
@@ -1263,7 +1263,8 @@ comm_point_tcp_handle_read(int fd, struct comm_point* c, int short_ok)
 #ifndef USE_WINSOCK
                if(errno == EINTR || errno == EAGAIN)
                        return 1;
-               log_err("read (in tcp r): %s", strerror(errno));
+               log_err_addr("read (in tcp r)", strerror(errno),
+                       &c->repinfo.addr, c->repinfo.addrlen);
 #else /* USE_WINSOCK */
                if(WSAGetLastError() == WSAECONNRESET)
                        return 0;
@@ -1273,11 +1274,10 @@ comm_point_tcp_handle_read(int fd, struct comm_point* c, int short_ok)
                        winsock_tcp_wouldblock(&c->ev->ev, EV_READ);
                        return 1;
                }
-               log_err("read (in tcp r): %s", 
-                       wsa_strerror(WSAGetLastError()));
+               log_err_addr("read (in tcp r)",
+                       wsa_strerror(WSAGetLastError()),
+                       &c->repinfo.addr, c->repinfo.addrlen);
 #endif
-               log_addr(0, "remote address is", &c->repinfo.addr,
-                       c->repinfo.addrlen);
                return 0;
        }
        sldns_buffer_skip(c->buffer, r);
@@ -1323,7 +1323,8 @@ comm_point_tcp_handle_write(int fd, struct comm_point* c)
                if(error != 0 && verbosity < 2)
                        return 0; /* silence lots of chatter in the logs */
                 else if(error != 0) {
-                       log_err("tcp connect: %s", strerror(error));
+                       log_err_addr("tcp connect", strerror(error),
+                               &c->repinfo.addr, c->repinfo.addrlen);
 #else /* USE_WINSOCK */
                /* examine error */
                if(error == WSAEINPROGRESS)
@@ -1334,10 +1335,9 @@ comm_point_tcp_handle_write(int fd, struct comm_point* c)
                } else if(error != 0 && verbosity < 2)
                        return 0;
                else if(error != 0) {
-                       log_err("tcp connect: %s", wsa_strerror(error));
+                       log_err_addr("tcp connect", wsa_strerror(error),
+                               &c->repinfo.addr, c->repinfo.addrlen);
 #endif /* USE_WINSOCK */
-                       log_addr(0, "remote address is", &c->repinfo.addr, 
-                               c->repinfo.addrlen);
                        return 0;
                }
        }
@@ -1361,13 +1361,19 @@ comm_point_tcp_handle_write(int fd, struct comm_point* c)
 #endif /* HAVE_WRITEV */
                if(r == -1) {
 #ifndef USE_WINSOCK
-#ifdef EPIPE
+#  ifdef EPIPE
                        if(errno == EPIPE && verbosity < 2)
                                return 0; /* silence 'broken pipe' */
-#endif
+  #endif
                        if(errno == EINTR || errno == EAGAIN)
                                return 1;
-                       log_err("tcp writev: %s", strerror(errno));
+#  ifdef HAVE_WRITEV
+                       log_err_addr("tcp writev", strerror(errno),
+                               &c->repinfo.addr, c->repinfo.addrlen);
+#  else /* HAVE_WRITEV */
+                       log_err_addr("tcp send s", strerror(errno),
+                               &c->repinfo.addr, c->repinfo.addrlen);
+#  endif /* HAVE_WRITEV */
 #else
                        if(WSAGetLastError() == WSAENOTCONN)
                                return 1;
@@ -1377,11 +1383,10 @@ comm_point_tcp_handle_write(int fd, struct comm_point* c)
                                winsock_tcp_wouldblock(&c->ev->ev, EV_WRITE);
                                return 1; 
                        }
-                       log_err("tcp send s: %s", 
-                               wsa_strerror(WSAGetLastError()));
+                       log_err_addr("tcp send s",
+                               wsa_strerror(WSAGetLastError()),
+                               &c->repinfo.addr, c->repinfo.addrlen);
 #endif
-                       log_addr(0, "remote address is", &c->repinfo.addr,
-                               c->repinfo.addrlen);
                        return 0;
                }
                c->tcp_byte_count += r;
@@ -1401,7 +1406,8 @@ comm_point_tcp_handle_write(int fd, struct comm_point* c)
 #ifndef USE_WINSOCK
                if(errno == EINTR || errno == EAGAIN)
                        return 1;
-               log_err("tcp send r: %s", strerror(errno));
+               log_err_addr("tcp send r", strerror(errno),
+                       &c->repinfo.addr, c->repinfo.addrlen);
 #else
                if(WSAGetLastError() == WSAEINPROGRESS)
                        return 1;
@@ -1409,11 +1415,9 @@ comm_point_tcp_handle_write(int fd, struct comm_point* c)
                        winsock_tcp_wouldblock(&c->ev->ev, EV_WRITE);
                        return 1; 
                }
-               log_err("tcp send r: %s", 
-                       wsa_strerror(WSAGetLastError()));
+               log_err_addr("tcp send r", wsa_strerror(WSAGetLastError()),
+                       &c->repinfo.addr, c->repinfo.addrlen);
 #endif
-               log_addr(0, "remote address is", &c->repinfo.addr,
-                       c->repinfo.addrlen);
                return 0;
        }
        sldns_buffer_skip(c->buffer, r);