From c19f818c526ec002e05ab3f79f6c8ec5652e0aa7 Mon Sep 17 00:00:00 2001 From: Wouter Wijngaards Date: Thu, 10 Apr 2014 14:40:20 +0000 Subject: [PATCH] - 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 --- doc/Changelog | 2 ++ services/listen_dnsport.c | 16 ++++------ services/outside_network.c | 13 ++++---- smallapp/unbound-control.c | 5 ++- util/net_help.c | 20 ++++++++++++ util/net_help.h | 10 ++++++ util/netevent.c | 62 ++++++++++++++++++++------------------ 7 files changed, 79 insertions(+), 49 deletions(-) diff --git a/doc/Changelog b/doc/Changelog index e4f20f3a9..9bda05fbc 100644 --- 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 49059f83a..badd303d9 100644 --- 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 3b685804f..4baa1080d 100644 --- 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 067e133fc..76de1b2d3 100644 --- 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 7f6daab4a..30d543e00 100644 --- 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 b92dd40e8..54f4c9c0e 100644 --- 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 189aaa4e4..421d1a1bd 100644 --- 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); -- 2.47.2