From 78956a97dfcd89e870e3ece51309cffdab7cbe9c Mon Sep 17 00:00:00 2001 From: Thomas Bernard Date: Tue, 21 Apr 2020 23:24:58 +0200 Subject: [PATCH] upnpstun.c: improve error and debug log --- miniupnpd/Changelog.txt | 3 +- miniupnpd/upnpstun.c | 172 ++++++++++++++++++++++++++++++---------- 2 files changed, 133 insertions(+), 42 deletions(-) diff --git a/miniupnpd/Changelog.txt b/miniupnpd/Changelog.txt index ac23a05..09a203a 100644 --- a/miniupnpd/Changelog.txt +++ b/miniupnpd/Changelog.txt @@ -1,8 +1,9 @@ -$Id: Changelog.txt,v 1.460 2020/04/12 17:27:31 nanard Exp $ +$Id: Changelog.txt,v 1.463 2020/04/21 21:20:04 nanard Exp $ 2020/04/21: Remove FW API detecting code from Makefile (BSD). generate bsdmake.inc netfilter: addmasqueraderule() even if internal/external ports are the same + improve error and debug log in upnpstun.c 2020/04/20: Fix "IGD2 Port Triggering" in update_portmapping() diff --git a/miniupnpd/upnpstun.c b/miniupnpd/upnpstun.c index 659451c..fcadcdb 100644 --- a/miniupnpd/upnpstun.c +++ b/miniupnpd/upnpstun.c @@ -1,4 +1,4 @@ -/* $Id: $ */ +/* $Id: upnpstun.c,v 1.5 2020/04/21 21:21:59 nanard Exp $ */ /* vim: tabstop=4 shiftwidth=4 noexpandtab * MiniUPnP project * http://miniupnp.free.fr/ or http://miniupnp.tuxfamily.org/ @@ -15,6 +15,7 @@ #include #include #include +#include #include #include @@ -22,6 +23,7 @@ #include "config.h" #endif +#include "upnputils.h" #include "upnpstun.h" #if defined(USE_NETFILTER) @@ -62,7 +64,7 @@ static void fill_request(unsigned char buffer[28], int change_ip, int change_por buffer[2] = 0x00; buffer[3] = 0x08; - /* Magic Cookie: 0x2120A442 */ + /* RFC5389 Magic Cookie: 0x2120A442 */ buffer[4] = 0x21; buffer[5] = 0x12; buffer[6] = 0xA4; @@ -99,6 +101,7 @@ static int resolve_stun_host(const char *stun_host, unsigned short stun_port, st struct addrinfo hints; struct addrinfo *result, *rp; char service[6]; + int r; if (stun_port == 0) stun_port = (unsigned short)3478; @@ -110,7 +113,10 @@ static int resolve_stun_host(const char *stun_host, unsigned short stun_port, st hints.ai_protocol = IPPROTO_UDP; hints.ai_flags = AI_NUMERICSERV; - if (getaddrinfo(stun_host, service, &hints, &result) != 0) { + r = getaddrinfo(stun_host, service, &hints, &result); + if (r != 0) { + syslog(LOG_ERR, "%s: getaddrinfo(%s, %s, ...) failed : %s", + "resolve_stun_host", stun_host, service, gai_strerror(r)); errno = EHOSTUNREACH; return -1; } @@ -127,8 +133,16 @@ static int resolve_stun_host(const char *stun_host, unsigned short stun_port, st freeaddrinfo(result); if (!have_sock) { + syslog(LOG_WARNING, "%s: failed to resolve IPv4 address for %s:%s", + "resolve_stun_host", stun_host, service); errno = EHOSTUNREACH; return -1; + } else { + char addr_str[48]; + if (sockaddr_to_string((struct sockaddr *)sock_addr, addr_str, sizeof(addr_str)) > 0) { + syslog(LOG_DEBUG, "%s: %s:%s => %s", + "resolve_stun_host", stun_host, service, addr_str); + } } return 0; @@ -142,8 +156,11 @@ static int stun_socket(unsigned short *local_port) struct sockaddr_in local_addr; fd = socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP); - if (fd < 0) + if (fd < 0) { + syslog(LOG_ERR, "%s: socket(AF_INET, SOCK_DGRAM, IPPROTO_UDP): %m", + "stun_socket"); return -1; + } memset(&local_addr, 0, sizeof(local_addr)); local_addr.sin_family = AF_INET; @@ -151,12 +168,16 @@ static int stun_socket(unsigned short *local_port) local_addr.sin_port = 0; if (bind(fd, (struct sockaddr *)&local_addr, sizeof(local_addr)) != 0) { + syslog(LOG_ERR, "%s: bind(): %m", + "stun_socket"); close(fd); return -1; } addr_len = sizeof(local_addr); if (getsockname(fd, (struct sockaddr *)&local_addr, &addr_len) != 0) { + syslog(LOG_ERR, "%s: getsockname(): %m", + "stun_socket"); close(fd); return -1; } @@ -173,12 +194,33 @@ static size_t receive_stun_response(int fd, unsigned char *buffer, unsigned char socklen_t peer_addr_len = sizeof(*peer_addr); len = recvfrom(fd, buffer, buffer_len, 0, (struct sockaddr *)peer_addr, &peer_addr_len); - if (len < 20 || peer_addr_len != sizeof(*peer_addr)) + if (len < 0) { + syslog(LOG_ERR, "%s: recvfrom(): %m", "receive_stun_response"); return 0; + } + if (peer_addr_len != sizeof(*peer_addr)) { + syslog(LOG_ERR, "%s: recvfrom(): peer_addr_len mismatch", + "receive_stun_response"); + return 0; + } + if (len < 20) { + syslog(LOG_WARNING, "%s: response too short : %ld", + "receive_stun_response", (long)len); + return 0; + } - /* Check that buffer is STUN message with class Response and Binding method with transaction id */ - if ((buffer[0] & 0xFF) != 0x01 || (buffer[1] & 0xEF) != 0x01 || memcmp(buffer+8, transaction_id, 12) != 0) + /* Check that buffer is STUN message with class Response + * and Binding method with transaction id */ + if ((buffer[0] & 0xFF) != 0x01 || (buffer[1] & 0xEF) != 0x01) { + syslog(LOG_WARNING, "%s: STUN message type is 0x%02x%02x", + "receive_stun_response", buffer[0], buffer[1]); return 0; + } + if (memcmp(buffer+8, transaction_id, 12) != 0) { + syslog(LOG_WARNING, "%s: transaction id mismatch", + "receive_stun_response"); + return 0; + } return len; } @@ -209,8 +251,12 @@ static int wait_for_stun_responses(int fds[4], unsigned char *transaction_ids[4] } ret = select(max_fd+1, &fdset, NULL, NULL, &timeout); - if (ret < 0) + if (ret < 0) { + if (errno == EINTR) + continue; + syslog(LOG_ERR, "%s: select(): %m", "wait_for_stun_responses"); return -1; + } if (ret == 0) return 0; @@ -236,13 +282,20 @@ static int parse_stun_response(unsigned char *buffer, size_t len, struct sockadd if (len < 20) return -1; - /* Check that buffer is STUN message with class Success Response and Binding method */ - if (buffer[0] != 0x01 || buffer[1] != 0x01) + syslog(LOG_DEBUG, "%s: Type 0x%04x, Length %hu, Magic Cookie %02x%02x%02x%02x", + "parse_stun_response", ((uint16_t)buffer[0] << 8) + buffer[1], + ((uint16_t)buffer[2] << 8) + buffer[3], + buffer[4], buffer[5], buffer[6], buffer[7]); + + /* Check that buffer is STUN message with class Response and Binding method */ + if (buffer[0] != 0x01 || (buffer[1] & 0xEF) != 0x01) return -1; /* Check that STUN message is not longer as buffer length */ - if (((size_t)buffer[2] << 8) + buffer[3] + 20 > len) + if (((size_t)buffer[2] << 8) + buffer[3] + 20 > len) { + syslog(LOG_ERR, "%s: truncated STUN response", "parse_stun_response"); return -1; + } ptr = buffer + 20; end = buffer + len; @@ -254,14 +307,18 @@ static int parse_stun_response(unsigned char *buffer, size_t len, struct sockadd attr_len = ((uint16_t)ptr[2] << 8) + ptr[3]; ptr += 4; - if (ptr + attr_len > end) + if (ptr + attr_len > end) { + syslog(LOG_WARNING, "%s: truncated attribute", "parse_stun_response"); break; + } - if (attr_type == 0x0001 || attr_type == 0x8020) { + switch (attr_type) { + case 0x0001: /* MAPPED-ADDRESS */ + case 0x8020: /* XOR-MAPPED-ADDRESS (2005 draft) */ /* Mapped Address or XOR Mapped Address */ if (attr_len == 8 && ptr[1] == 1) { /* IPv4 address */ - if (attr_type == 0x8020) { + if ((attr_type & 0x7fff) == 0x0020) { /* Restore XOR Mapped Address */ ptr[2] ^= buffer[4]; ptr[3] ^= buffer[5]; @@ -276,11 +333,15 @@ static int parse_stun_response(unsigned char *buffer, size_t len, struct sockadd mapped_addr->sin_addr.s_addr = htonl(((uint32_t)ptr[4] << 24) + (ptr[5] << 16) + (ptr[6] << 8) + ptr[7]); /* Prefer XOR Mapped Address, some NATs change IP addresses in UDP packets */ - if (attr_type == 0x8020) + if ((attr_type & 0x7fff) == 0x0020) return 0; have_address = 1; } + break; + default: + syslog(LOG_WARNING, "%s: unknown attribute type 0x%04x (len=%hu)", + "parse_stun_response", attr_type, attr_len); } ptr += attr_len; @@ -289,8 +350,11 @@ static int parse_stun_response(unsigned char *buffer, size_t len, struct sockadd return have_address ? 0 : -1; } -/* Perform main STUN operation, return external IP address and check if host is behind restrictive NAT */ -/* Restrictive NAT means any NAT which do some filtering and which is not static 1:1, basically NAT which is not usable for port forwarding */ +/* Perform main STUN operation, return external IP address and check + * if host is behind restrictive NAT. + * Restrictive NAT means any NAT which do some filtering and + * which is not static 1:1, basically NAT which is not usable + * for port forwarding */ int perform_stun(const char *if_name, const char *if_addr, const char *stun_host, unsigned short stun_port, struct in_addr *ext_addr, int *restrictive_nat) { int fds[4]; @@ -300,7 +364,7 @@ int perform_stun(const char *if_name, const char *if_addr, const char *stun_host size_t responses_sizes[4]; unsigned char requests[4][28]; unsigned char *transaction_ids[4]; - int have_mapped_addrs[4]; + int have_mapped_addr, mapped_addrs_count; struct sockaddr_in remote_addr, peer_addrs[4], mapped_addrs[4]; unsigned short local_ports[4]; int have_ext_addr; @@ -325,21 +389,32 @@ int perform_stun(const char *if_name, const char *if_addr, const char *stun_host fill_request(requests[i], i/2, i%2); transaction_ids[i] = requests[i]+8; - } + syslog(LOG_INFO, "%s: local ports %hu %hu %hu %hu", + "perform_stun", local_ports[0], local_ports[1], + local_ports[2], local_ports[3]); + /* Unblock local ports */ - for (i = 0; i < 4; ++i) - add_filter_rule2(if_name, NULL, if_addr, local_ports[i], local_ports[i], IPPROTO_UDP, "stun test"); + for (i = 0; i < 4; ++i) { + if (add_filter_rule2(if_name, NULL, if_addr, local_ports[i], local_ports[i], IPPROTO_UDP, "stun test") < 0) { + syslog(LOG_ERR, "%s: add_filter_rule2(..., %hu, ...) FAILED", + "perform_stun", local_ports[i]); + } + } /* Send STUN requests and wait for responses */ for (j = 0; j < 3; ++j) { for (i = 0; i < 4; ++i) { + ssize_t n; if (responses_lens[i]) continue; - if (sendto(fds[i], requests[i], sizeof(requests[i]), 0, (struct sockaddr *)&remote_addr, sizeof(remote_addr)) != sizeof(requests[i])) + n = sendto(fds[i], requests[i], sizeof(requests[i]), 0, (struct sockaddr *)&remote_addr, sizeof(remote_addr)); + if (n != sizeof(requests[i])) { + syslog(LOG_ERR, "%s: #%d,%d sendto(): %m", "perform_stun", j, i); break; + } } if (wait_for_stun_responses(fds, transaction_ids, responses, responses_sizes, peer_addrs, responses_lens) != 0) @@ -358,14 +433,16 @@ int perform_stun(const char *if_name, const char *if_addr, const char *stun_host /* Parse received STUN messages */ have_ext_addr = 0; + have_mapped_addr = 0; + mapped_addrs_count = 0; for (i = 0; i < 4; ++i) { - if (parse_stun_response(responses[i], responses_lens[i], &mapped_addrs[i]) == 0) - have_mapped_addrs[i] = 1; - else - have_mapped_addrs[i] = 0; - if (!have_ext_addr && have_mapped_addrs[i]) { - memcpy(ext_addr, &mapped_addrs[i].sin_addr, sizeof(*ext_addr)); - have_ext_addr = 1; + if (parse_stun_response(responses[i], responses_lens[i], &mapped_addrs[i]) == 0) { + mapped_addrs_count++; + have_mapped_addr |= (1 << i); + if (!have_ext_addr) { + memcpy(ext_addr, &mapped_addrs[i].sin_addr, sizeof(*ext_addr)); + have_ext_addr = 1; + } } } @@ -375,42 +452,54 @@ int perform_stun(const char *if_name, const char *if_addr, const char *stun_host return -1; } - for (i = 0; i < 4; ++i) { - if (!have_mapped_addrs[i]) { - /* We have not received all four responses, therefore NAT or firewall is doing some filtering */ - *restrictive_nat = 1; - return 0; - } + *restrictive_nat = 0; + + if (mapped_addrs_count < 4) { + /* We have not received all four responses, + * therefore NAT or firewall is doing some filtering */ + syslog(LOG_NOTICE, "%s: %d response out of 4 received", + "perform_stun", mapped_addrs_count); + *restrictive_nat = 1; } if (memcmp(&remote_addr, &peer_addrs[0], sizeof(peer_addrs[0])) != 0) { - /* We received STUN response from different address even we did not asked for it, so some strange NAT is active */ + /* We received STUN response from different address + * even we did not asked for it, so some strange NAT is active */ + syslog(LOG_NOTICE, "%s: address changed", + "perform_stun"); *restrictive_nat = 1; - return 0; } for (i = 0; i < 4; ++i) { + if (!(have_mapped_addr & (1 << i))) + continue; if (ntohs(mapped_addrs[i].sin_port) != local_ports[i] || memcmp(&mapped_addrs[i].sin_addr, ext_addr, sizeof(*ext_addr)) != 0) { - /* External IP address or port was changed, therefore symmetric NAT is active */ + /* External IP address or port was changed, + * therefore symmetric NAT is active */ + syslog(LOG_NOTICE, "%s: #%d external address or port changed", + "perform_stun", i); *restrictive_nat = 1; - return 0; } } /* Otherwise we are either directly connected or behind unrestricted NAT 1:1 */ /* There is no filtering, so port forwarding would work fine */ - *restrictive_nat = 0; return 0; } #ifdef TEST_LINUX_DEBUG_APP /* This linux test application for debugging purposes can be compiled as: */ -/* gcc upnpstun.c -o upnpstun -g3 -W -Wall -O2 -DTEST_LINUX_DEBUG_APP */ +/* gcc upnpstun.c upnputils.o -o upnpstun -g3 -W -Wall -O2 -DTEST_LINUX_DEBUG_APP */ #include #include +#include "upnpglobalvars.h" +struct lan_addr_list lan_addrs; +int runtime_flags = 0; +time_t startup_time = 0; + static int add_filter_rule2(const char *ifname, const char *rhost, const char *iaddr, unsigned short eport, unsigned short iport, int proto, const char *desc) { char buffer[100]; @@ -450,6 +539,7 @@ int main(int argc, char *argv[]) srandom(time(NULL) * getpid()); + openlog("upnpstun", LOG_CONS|LOG_PERROR, LOG_USER); ret = perform_stun(NULL, NULL, argv[1], atoi(argv[2]), &ext_addr, &restrictive_nat); if (ret != 0) { printf("STUN Failed: %s\n", strerror(errno));