search

pupnp / pupnp

libupnp: Build UPnP-compliant control points, devices, and bridges on several operating systems.
https://pupnp.github.io/pupnp
BSD 3-Clause "New" or "Revised" License
352 stars 117 forks source link

Tests not built on 32bit due to large file support #173

Closed kyak closed 3 years ago

kyak commented 4 years ago

Hi!

Using 32-bit (ARM) Linux here and the latest git version of pupnp.

Build fails in test/test_init.c:

[skip]
make  test_init test_url test_log test_list                                     
[skip]
  CC       test/test_init.o
In file included from ../upnp/inc/upnp.h:405,
                 from test/test_init.c:34:
../upnp/inc/FileInfo.h:21:2: error: #error libupnp uses large file support, so 
users must do that, too
   21 | #error libupnp uses large file support, so users must do that, too
      |  ^~~~~

This seems to be related to #94, but this time tests fail, not samples.

mrjimenez commented 4 years ago

Hi Kyak,

I have a made a buildroot generated toolchain and I cannot reproduce the issue (using master here):

/home/pupnp/upnp git:(master ✔) $ make check Making check in . make[1]: Entering directory '/home/pupnp/upnp' make test_init test_url test_log test_list make[2]: Entering directory '/home/pupnp/upnp' CC test/test_init.o CCLD test_init CC test/test_url.o test/test_url.c:72:2: warning: missing initializer for field ‘error’ of ‘const struct test’ [-Wmissing-field-initializers] 72 | TEST(NULL, ABS_URL1, ABS_URL1), | ^~~~

The file seems to be correctly generated:

/home/pupnp git:(master ✔) $ file ./upnp/.libs/test_init ./upnp/.libs/test_init: ELF 32-bit LSB executable, ARM, EABI5 version 1 (SYSV), dynamically linked, interpreter /lib/ld-linux.so.3, for GNU/Linux 4.9.0, not stripped

kyak commented 4 years ago

Hi mrjimenez,

Thanks for looking into this!

Now, with the latest master, the situation is different as of my original report.

The "test_init" binary build fine:

libupnp-git/src/pupnp/upnp/.libs/test_init: ELF 32-bit LSB pie executable, ARM, EABI5 version 1 (SYSV), dynamically linked, interpreter /lib/ld-linux-armhf.so.3, BuildID[sha1]=74f8bcc9f3f44a01ece39bf1d2535a385c6a56cf, for GNU/Linux 3.2.0, not stripped

However, the test itself fails:

cat libupnp-git/src/pupnp/upnp/test_init.log

UPNP_VERSION_STRING = "1.14.0"
UPNP_VERSION_MAJOR  = 1
UPNP_VERSION_MINOR  = 14
UPNP_VERSION_PATCH  = 0
UPNP_VERSION        = 11400

UPNP_HAVE_DEBUG         = no
UPNP_HAVE_CLIENT        = yes
UPNP_HAVE_DEVICE        = yes
UPNP_HAVE_WEBSERVER     = yes
UPNP_HAVE_TOOLS         = yes

Initializing UPnP ... 
** ERROR UpnpInit2(): -206 UPNP_E_LISTEN
FAIL test_init (exit status: 1)
mrjimenez commented 4 years ago

Could you please configure it with --enable-debug and post the log file (upnp/test-suite.log)? It should have an output more or less like this:

2020-06-17T22:22:38.7127340Z ========================================= 2020-06-17T22:22:38.7128470Z libupnp 1.14.0: upnp/test-suite.log 2020-06-17T22:22:38.7128610Z ========================================= 2020-06-17T22:22:38.7128670Z 2020-06-17T22:22:38.7128760Z # TOTAL: 4 2020-06-17T22:22:38.7129280Z # PASS: 3 2020-06-17T22:22:38.7129380Z # SKIP: 0 2020-06-17T22:22:38.7129470Z # XFAIL: 0 2020-06-17T22:22:38.7129560Z # FAIL: 1 2020-06-17T22:22:38.7129640Z # XPASS: 0 2020-06-17T22:22:38.7129720Z # ERROR: 0 2020-06-17T22:22:38.7129780Z 2020-06-17T22:22:38.7130040Z .. contents:: :depth: 2 2020-06-17T22:22:38.7130100Z 2020-06-17T22:22:38.7130190Z FAIL: testinit 2020-06-17T22:22:38.7130280Z =============== 2020-06-17T22:22:38.7130330Z 2020-06-17T22:22:38.7130950Z 2020-06-17 22:22:37 UPNP-API-2: Thread:0x1129EEDC0 [../../../upnp/src/api/upnpapi.c:373]: Inside UpnpInitPreamble 2020-06-17T22:22:38.7131480Z 2020-06-17 22:22:37 UPNP-API-2: Thread:0x1129EEDC0 [../../../upnp/src/api/upnpapi.c:389]: Trying a write lock 2020-06-17T22:22:38.7131980Z 2020-06-17 22:22:37 UPNP-API-2: Thread:0x1129EEDC0 [../../../upnp/src/api/upnpapi.c:389]: Write lock acquired 2020-06-17T22:22:38.7132470Z 2020-06-17 22:22:37 UPNP-API-2: Thread:0x1129EEDC0 [../../../upnp/src/api/upnpapi.c:393]: Trying Unlock 2020-06-17T22:22:38.7132990Z 2020-06-17 22:22:37 UPNP-API-2: Thread:0x1129EEDC0 [../../../upnp/src/api/upnpapi.c:393]: Unlocked rwlock 2020-06-17T22:22:38.7133500Z 2020-06-17 22:22:37 UPNP-API-2: Thread:0x1129EEDC0 [../../../upnp/src/api/upnpapi.c:505]: UpnpInit2 with IfName=, DestPort=0. 2020-06-17T22:22:38.7134740Z 2020-06-17 22:22:37 UPNP-API-2: Thread:0x1129EEDC0 [../../../upnp/src/api/upnpapi.c:4101]: Interface name=en0, index=4, v4=10.79.1.143, v6=::, ULA or GUA v6=:: 2020-06-17T22:22:38.7135270Z 2020-06-17 22:22:37 UPNP-API_-2: Thread:0x1129EEDC0 [../../../upnp/src/api/upnpapi.c:443]: Entering UpnpInitStartServers 2020-06-17T22:22:38.7135800Z 2020-06-17 22:22:37 UPNP-MSER-2: Thread:0x1129EEDC0 [../../../upnp/src/genlib/miniserver/miniserver.c:797]: get_miniserver_sockets: bind successful 2020-06-17T22:22:38.7136330Z 2020-06-17 22:22:37 UPNP-MSER-2: Thread:0x1129EEDC0 [../../../upnp/src/genlib/miniserver/miniserver.c:482]: sockfd = 3, .... port = 49152 2020-06-17T22:22:38.7136850Z 2020-06-17 22:22:37 UPNP-MSER-2: Thread:0x1129EEDC0 [../../../upnp/src/genlib/miniserver/miniserver.c:482]: sockfd = 4, .... port = 49152 2020-06-17T22:22:38.7137910Z 2020-06-17 22:22:37 UPNP-MSER-2: Thread:0x1129EEDC0 [../../../upnp/src/genlib/miniserver/miniserver.c:482]: sockfd = 5, .... port = 49153 2020-06-17T22:22:38.7138440Z 2020-06-17 22:22:37 UPNP-MSER-2: Thread:0x1129EEDC0 [../../../upnp/src/genlib/miniserver/miniserver.c:482]: sockfd = 6, .... port = 53210 2020-06-17T22:22:38.7139000Z 2020-06-17 22:22:37 UPNP-SSDP-0: Thread:0x1129EEDC0 [../../../upnp/src/ssdp/ssdp_server.c:1000]: Error in setsockopt() IPV6_JOINGROUP (join multicast group): Invalid argument 2020-06-17T22:22:38.7139630Z 2020-06-17 22:22:37 UPNP-API-0: Thread:0x1129EEDC0 [../../../upnp/src/api/upnpapi.c:456]: Miniserver failed to start 2020-06-17 22:22:37 UPNP-API-2: Thread:0x1129EEDC0 [../../../upnp/src/api/upnpapi.c:628]: Inside UpnpFinish: UpnpSdkInit is 1 2020-06-17T22:22:38.7140160Z 2020-06-17 22:22:37 UPNP-API-2: Thread:0x1129EEDC0 [../../../upnp/src/api/upnpapi.c:635]: UpnpFinish: UpnpSdkInit is ONE 2020-06-17T22:22:38.7140680Z 2020-06-17 22:22:37 UPNP-API_-2: Thread:0x1129EEDC0 [../../../upnp/src/api/upnpapi.c:638]: Send Thread Pool 2020-06-17T22:22:38.7140810Z High Jobs pending: 0 2020-06-17T22:22:38.7140890Z Med Jobs Pending: 0 2020-06-17T22:22:38.7140990Z Low Jobs Pending: 0 2020-06-17T22:22:38.7141080Z Average wait in High Q in milliseconds: 0.000000 2020-06-17T22:22:38.7141180Z Average wait in Med Q in milliseconds: 0.000000 2020-06-17T22:22:38.7141280Z Average wait in Low Q in milliseconds: 0.000000 2020-06-17T22:22:38.7141370Z Max Threads Used: 3 2020-06-17T22:22:38.7141460Z Worker Threads: 0 2020-06-17T22:22:38.7141540Z Persistent Threads: 1 2020-06-17T22:22:38.7141640Z Idle Threads: 2 2020-06-17T22:22:38.7141730Z Total Threads: 3 2020-06-17T22:22:38.7141820Z Total Work Time: 0.000000 2020-06-17T22:22:38.7141910Z Total Idle Time: 0.000000

Best regards, Marcelo.

kyak commented 3 years ago

Hi Marcelo,

Here you go: test-suite.log

mrjimenez commented 3 years ago

I have tested in an ARM32 system and it worked fine.

The relevant part of log:

FAIL: test_init

2020-06-20 12:05:12 UPNP-API-2: Thread:0xB6FB7010 [src/api/upnpapi.c:373]: Inside UpnpInitPreamble 2020-06-20 12:05:12 UPNP-API-2: Thread:0xB6FB7010 [src/api/upnpapi.c:389]: Trying a write lock 2020-06-20 12:05:12 UPNP-API-2: Thread:0xB6FB7010 [src/api/upnpapi.c:389]: Write lock acquired 2020-06-20 12:05:12 UPNP-API-2: Thread:0xB6FB7010 [src/api/upnpapi.c:393]: Trying Unlock 2020-06-20 12:05:12 UPNP-API-2: Thread:0xB6FB7010 [src/api/upnpapi.c:393]: Unlocked rwlock 2020-06-20 12:05:12 UPNP-API-2: Thread:0xB6FB7010 [src/api/upnpapi.c:505]: UpnpInit2 with IfName=, DestPort=0. 2020-06-20 12:05:12 UPNP-API-2: Thread:0xB6FB7010 [src/api/upnpapi.c:4101]: Interface name=eth0, index=2, v4=192.168.1.2, v6=fe80:0000:0000:0000:021e:06ff:fe37:0e61, ULA or GUA v6= 2020-06-20 12:05:12 UPNP-API-2: Thread:0xB6FB7010 [src/api/upnpapi.c:443]: Entering UpnpInitStartServers 2020-06-20 12:05:12 UPNP-MSER-2: Thread:0xB6FB7010 [src/genlib/miniserver/miniserver.c:644]: get_miniserver_sockets: resuseaddr is set. 2020-06-20 12:05:12 UPNP-MSER-2: Thread:0xB6FB7010 [src/genlib/miniserver/miniserver.c:797]: get_miniserversockets: bind successful 2020-06-20 12:05:12 UPNP-MSER-2: Thread:0xB6FB7010 [src/genlib/miniserver/miniserver.c:482]: sockfd = 3, .... port = 49153 2020-06-20 12:05:12 UPNP-MSER-2: Thread:0xB6FB7010 [src/genlib/miniserver/miniserver.c:482]: sockfd = 4, .... port = 49153 2020-06-20 12:05:12 UPNP-MSER-2: Thread:0xB6FB7010 [src/genlib/miniserver/miniserver.c:848]: mserv start: Error in IPv6 listen(): Address already in use 2020-06-20 12:05:12 UPNP-API-0: Thread:0xB6FB7010 [src/api/upnpapi.c:456]: Miniserver failed to start 2020-06-20 12:05:12 UPNP-API-2: Thread:0xB6FB7010 [src/api/upnpapi.c:628]: Inside UpnpFinish: UpnpSdkInit is 1 2020-06-20 12:05:12 UPNP-API-2: Thread:0xB6FB7010 [src/api/upnpapi.c:635]: UpnpFinish: UpnpSdkInit is ONE 2020-06-20 12:05:12 UPNP-API_-2: Thread:0xB6FB7010 [src/api/upnpapi.c:638]: Send Thread Pool

Address already in use? Is there another server running in your system?

Regards, Marcelo.

kyak commented 3 years ago

I have both minidlna and gerbera running, but stopping them didn't solve the problem.

What's interesting is that the test_init fails to listen on IPv6 only, but listens fine on IPv4.

I don't use and didn't configure IPv6 on this interface, so maybe test_init shouldn't try to listen on this interface?

mrjimenez commented 3 years ago

I believe you have no option. If IPV6 is configured in your machine and you have not passed an interface to upnpinit2(), it will bind on all interfaces times {IPV4, IPV6}.

Anyway, there is something odd. Listen() should not fail with EADDRINUSE. Bind() could, but the error condition seems to be treated. I read the code but still don't get it.

kyak commented 3 years ago

Hi Marcelo,

Sorry, it took me a while.

First of all, there really was a conflict before I had stopped gerbera. The conflicting port was 49152. I ran test_init with strace and noticed that bind() returns EADDRINUSE. So, "make check" will fail on every machine running gerbera, I suppose. Is there something that can be done - like, for example, binding to a random (OS chosen) port in test_init?

Secondly, the problem doesn't go away even after I stop gerbera. Once again, I ran test_init with strace and can see that bind() returns success. But listen still returns -1, which is interpreted as EADDRINUSE. As you mentioned above, listen can't return EADDRINUSE, so there might be a problem with the test checking errno.

So here is the result of _LANG=C strace -f -s 1000 ./testinit 2>&1 test.log

mrjimenez commented 3 years ago

Hi kyak,

From your log, it seems to be a fact that in spite not beeing documented as so, listen() can indeed fail with EADDRINUSE. Still I am unable to find any references for that on the internet and I am still hesitant to read the glibc code, although it is probably the next unavoidable step.

Could you please run netstat -ntlp just before and after test_init?

Regards, Marcelo.

kyak commented 3 years ago

Hi Marcelo,

The output of netstat is identical before and after running test_init:

$ netstat -ntl
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State      
tcp        0      0 0.0.0.0:8200            0.0.0.0:*               LISTEN     
tcp        0      0 0.0.0.0:5355            0.0.0.0:*               LISTEN     
tcp        0      0 127.0.0.1:8080          0.0.0.0:*               LISTEN     
tcp        0      0 127.0.0.53:53           0.0.0.0:*               LISTEN     
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN     
tcp        0      0 127.0.0.1:5432          0.0.0.0:*               LISTEN     
tcp        0      0 0.0.0.0:443             0.0.0.0:*               LISTEN     
tcp        0      0 127.0.0.1:8384          0.0.0.0:*               LISTEN     
tcp6       0      0 :::6891                 :::*                    LISTEN     
tcp6       0      0 :::5355                 :::*                    LISTEN     
tcp6       0      0 :::22000                :::*                    LISTEN     
tcp6       0      0 :::22                   :::*                    LISTEN     
tcp6       0      0 ::1:5432                :::*                    LISTEN

Another thing I've noticed from strace output is that test_init tries to bind and listen three times:

$ LANG=C strace -f -s 1000 ./test_init 2>&1 | grep -E 'bind|listen'
[pid   939] bind(3, {sa_family=AF_INET, sin_port=htons(49152), sin_addr=inet_addr("192.168.1.2")}, 16) = 0
[pid   939] bind(4, {sa_family=AF_INET6, sin6_port=htons(49152), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "fe80::21e:6ff:fe37:e61", &sin6_addr), sin6_scope_id=if_nametoindex("eth0")}, 28) = 0
[pid   939] bind(5, {sa_family=AF_INET6, sin6_port=htons(49152), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::", &sin6_addr), sin6_scope_id=0}, 28) = 0
[pid   939] write(2, "get_miniserver_sockets: bind successful\n", 40get_miniserver_sockets: bind successful
[pid   939] listen(3, 4096)             = 0
[pid   939] listen(4, 4096)             = 0
[pid   939] listen(5, 4096)             = -1 EADDRINUSE (Address already in use)
[pid   939] write(2, "mserv start: Error in IPv6 listen(): Address already in use\n", 60mserv start: Error in IPv6 listen(): Address already in use

Clearly, the first two times and binds and listens to IPv4 and IPv6 interfaces. But the third time, it tries to bind and listen on the same IPv6 interface. Is it expected? How many times it binds and listens on your machine in the test?

These are my interfaces:

$ ip a
1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc noqueue state UNKNOWN group default qlen 1000
    link/loopback 00:00:00:00:00:00 brd 00:00:00:00:00:00
    inet 127.0.0.1/8 scope host lo
       valid_lft forever preferred_lft forever
    inet6 ::1/128 scope host 
       valid_lft forever preferred_lft forever
2: eth0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc fq_codel state UP group default qlen 1000
    link/ether DE:AD:BE:EF:DE:AD brd ff:ff:ff:ff:ff:ff
    inet 192.168.1.2/24 brd 192.168.1.255 scope global dynamic eth0
       valid_lft 42486sec preferred_lft 42486sec
    inet6 fe80::21e:6ff:fe37:e61/64 scope link 
       valid_lft forever preferred_lft forever

The IPv6 is not configured, but automatically set up as link-local address.

comminux commented 3 years ago

I have a similar problem but on 64-bit (Arch Linux)

libupnp-git build from master branch with:

/bootstrap
  ./configure \
    --prefix="/usr" \
    --enable-reuseaddr \
    --enable-debug
  make
cd "pupnp"
make check
[ranko@saoji trizen]$ netstat -ntlp
(Not all processes could be identified, non-owned process info
 will not be shown, you would have to be root to see it all.)
Active Internet connections (only servers)
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name    
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      -                   
tcp6       0      0 :::22                   :::*                    LISTEN      -

libupnp 1.14.0: upnp/test-suite.log - https://gist.github.com/Comminux/f9e418ce5729da542fafcc89bf25358d

mrjimenez commented 3 years ago

Hi Kyak and Comminux,

Comminux, indeed seems to be the same problem.

Kyak, I am sorry I missed the last part of your post. Maybe you edited some time after and I did not receive an e-mail with the whole message.

The test performs four calls to bind() and four calls to listen() as part of the initialization procedure. In my machine, I get this:

2020-07-17 18:37:37 UPNP-API-2: Thread:0x7FA1B3523B80 [src/api/upnpapi.c:373]: Inside UpnpInitPreamble 2020-07-17 18:37:37 UPNP-API-2: Thread:0x7FA1B3523B80 [src/api/upnpapi.c:389]: Trying a write lock 2020-07-17 18:37:37 UPNP-API-2: Thread:0x7FA1B3523B80 [src/api/upnpapi.c:389]: Write lock acquired 2020-07-17 18:37:37 UPNP-API-2: Thread:0x7FA1B3523B80 [src/api/upnpapi.c:393]: Trying Unlock 2020-07-17 18:37:37 UPNP-API-2: Thread:0x7FA1B3523B80 [src/api/upnpapi.c:393]: Unlocked rwlock 2020-07-17 18:37:37 UPNP-API-2: Thread:0x7FA1B3523B80 [src/api/upnpapi.c:505]: UpnpInit2 with IfName=, DestPort=0. 2020-07-17 18:37:37 UPNP-API-2: Thread:0x7FA1B3523B80 [src/api/upnpapi.c:4101]: Interface name=enp2s0, index=2, v4=192.168.1.2, v6=fe80:0000: 2020-07-17 18:37:37 UPNP-API-2: Thread:0x7FA1B3523B80 [src/api/upnpapi.c:443]: Entering UpnpInitStartServers 2020-07-17 18:37:37 UPNP-MSER-2: Thread:0x7FA1B3523B80 [src/genlib/miniserver/miniserver.c:797]: get_miniserversockets: bind successful 2020-07-17 18:37:37 UPNP-MSER-2: Thread:0x7FA1B3523B80 [src/genlib/miniserver/miniserver.c:482]: sockfd = 3, .... port = 49152 2020-07-17 18:37:37 UPNP-MSER-2: Thread:0x7FA1B3523B80 [src/genlib/miniserver/miniserver.c:482]: sockfd = 4, .... port = 49152 2020-07-17 18:37:37 UPNP-MSER-2: Thread:0x7FA1B3523B80 [src/genlib/miniserver/miniserver.c:482]: sockfd = 5, .... port = 49153 2020-07-17 18:37:37 UPNP-MSER-2: Thread:0x7FA1B3523B80 [src/genlib/miniserver/miniserver.c:482]: sockfd = 6, .... port = 42254 2020-07-17 18:37:37 UPNP-API-2: Thread:0x7FA1B3523B80 [src/api/upnpapi.c:475]: Exiting UpnpInitStartServers 2020-07-17 18:37:37 UPNP-API-2: Thread:0x7FA1B3523B80 [src/api/upnpapi.c:628]: Inside UpnpFinish: UpnpSdkInit is 1 2020-07-17 18:37:37 UPNP-API-2: Thread:0x7FA1B3523B80 [src/api/upnpapi.c:635]: UpnpFinish: UpnpSdkInit is ONE 2020-07-17 18:37:37 UPNP-API_-2: Thread:0x7FA1B3523B80 [src/api/upnpapi.c:638]: Send Thread Pool

But look at my strace as compared to yours:

write(2, "Entering UpnpInitStartServers\n", 30Entering UpnpInitStartServers ) = 30 socket(AF_INET, SOCK_STREAM, IPPROTO_IP) = 3 socket(AF_INET6, SOCK_STREAM, IPPROTO_IP) = 4 setsockopt(4, SOL_IPV6, IPV6_V6ONLY, [1], 4) = 0 socket(AF_INET6, SOCK_STREAM, IPPROTO_IP) = 5 setsockopt(5, SOL_IPV6, IPV6_V6ONLY, [1], 4) = 0 bind(3, {sa_family=AF_INET, sin_port=htons(49152), sin_addr=inet_addr("192.168.1.2")}, 16) = 0 bind(4, {sa_family=AF_INET6, sin6_port=htons(49152), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "fe80::1e1b:dff:fef0:90d5", &sin6_addr), sin6_scope_id=if_nametoindex("enp2s0")}, 28) = 0 bind(5, {sa_family=AF_INET6, sin6_port=htons(49152), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::", &sin6_addr), sin6_scope_id=0}, 28) = -1 EADDRINUSE (Address already in use) bind(5, {sa_family=AF_INET6, sin6_port=htons(49153), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::", &sin6_addr), sin6_scope_id=0}, 28) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1444, ...}) = 0 write(2, "2020-07-17 19:05:29 UPNP-MSER-2:"..., 972020-07-17 19:05:29 UPNP-MSER-2: Thread:0x7F70D5710B80 [src/genlib/miniserver/miniserver.c:797]: ) = 97 write(2, "get_miniserver_sockets: bind suc"..., 40get_miniserver_sockets: bind successful ) = 40 listen(3, 4096) = 0 getsockname(3, {sa_family=AF_INET, sin_port=htons(49152), sin_addr=inet_addr("192.168.1.2")}, [128->16]) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1444, ...}) = 0 write(2, "2020-07-17 19:05:29 UPNP-MSER-2:"..., 972020-07-17 19:05:29 UPNP-MSER-2: Thread:0x7F70D5710B80 [src/genlib/miniserver/miniserver.c:482]: ) = 97 write(2, "sockfd = 3, .... port = 49152\n", 30sockfd = 3, .... port = 49152 ) = 30 listen(4, 4096) = 0 getsockname(4, {sa_family=AF_INET6, sin6_port=htons(49152), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "fe80::1e1b:dff:fef0:90d5", &sin6_addr), sin6_scope_id=if_nametoindex("enp2s0")}, [128->28]) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1444, ...}) = 0 write(2, "2020-07-17 19:05:29 UPNP-MSER-2:"..., 972020-07-17 19:05:29 UPNP-MSER-2: Thread:0x7F70D5710B80 [src/genlib/miniserver/miniserver.c:482]: ) = 97 write(2, "sockfd = 4, .... port = 49152\n", 30sockfd = 4, .... port = 49152 ) = 30 listen(5, 4096) = 0 getsockname(5, {sa_family=AF_INET6, sin6_port=htons(49153), sin6_flowinfo=htonl(0), inet_pton(AF_INET6, "::", &sin6_addr), sin6_scope_id=0}, [128->28]) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1444, ...}) = 0 write(2, "2020-07-17 19:05:29 UPNP-MSER-2:"..., 972020-07-17 19:05:29 UPNP-MSER-2: Thread:0x7F70D5710B80 [src/genlib/miniserver/miniserver.c:482]: ) = 97 write(2, "sockfd = 5, .... port = 49153\n", 30sockfd = 5, .... port = 49153 ) = 30 socket(AF_INET, SOCK_DGRAM, IPPROTO_IP) = 6 bind(6, {sa_family=AF_INET, sin_port=htons(0), sin_addr=inet_addr("127.0.0.1")}, 16) = 0 getsockname(6, {sa_family=AF_INET, sin_port=htons(43162), sin_addr=inet_addr("127.0.0.1")}, [128->16]) = 0 stat("/etc/localtime", {st_mode=S_IFREG|0644, st_size=1444, ...}) = 0 write(2, "2020-07-17 19:05:29 UPNP-MSER-2:"..., 972020-07-17 19:05:29 UPNP-MSER-2: Thread:0x7F70D5710B80 [src/genlib/miniserver/miniserver.c:482]: ) = 97 write(2, "sockfd = 6, .... port = 43162\n", 30sockfd = 6, .... port = 43162 ) = 30

In my case the first bind(5,) fails with EADDRINUSE, which is ok, and the call is reissued succeeding. In your case, bind(5,) succeeds and listen(5,) fails with EADDRINUSE, which is an unexpected error code from listen().

The issue here seems to be related to a non-compliance of the network call. Which is extremely weird, I will have to dig more into that, any ideas are welcome.

Best regards, Marcelo.

kyak commented 3 years ago

Hi Marcelo,

Both Communix and me are running Arch Linux (I have no idea how I missed mentioning that in the first post). This means latest glibc (2.31 at the moment). I think this is our main suspect now.

mrjimenez commented 3 years ago

Ops, I did let something slip. Thanks to Comminux, I was able to reproduce the problem. Using --enable-reuseaddr makes the problem show here.

Maybe this Stackoverflow answer sheds some light on the problem.

I am still digesting it, but it is likely that the current implementation is not dealing correctly with this flag.

mrjimenez commented 3 years ago

Hi Kyak and Comminux,

Please test the latest master HEAD, the problem should be fixed.

Regards, Marcelo.

kyak commented 3 years ago

Hi Marcelo,

Thank you for thix fix! It works fine now.

mrjimenez commented 3 years ago

Ok, I will close the issue then.

Thank you very much for your help.