Bad socket issue after extended internet outage

[aarond10]

I was running with valgrind but this was producing so many messages that I lost the top of my scrollback buffer. Internet was out for about 8 hours overnight. Haven't had a chance to dig into it yet.

==4148834== Warning: invalid file descriptor 1031 in syscall openat()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall openat()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall openat()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall openat()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
^C==4148834== Warning: invalid file descriptor 1031 in syscall openat()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
==4148834== Warning: invalid file descriptor 1031 in syscall socket()
[S] 1623021947.296124 stat.c:16 2 0 0 81 0 4 0 2
==4148834== 
==4148834== HEAP SUMMARY:
==4148834==     in use at exit: 8,117 bytes in 20 blocks
==4148834==   total heap usage: 2,137,891,816 allocs, 2,137,891,796 frees, 201,899,765,715 bytes allocated
==4148834== 
==4148834== LEAK SUMMARY:
==4148834==    definitely lost: 0 bytes in 0 blocks
==4148834==    indirectly lost: 0 bytes in 0 blocks
==4148834==      possibly lost: 0 bytes in 0 blocks
==4148834==    still reachable: 8,117 bytes in 20 blocks
==4148834==         suppressed: 0 bytes in 0 blocks
==4148834== Rerun with --leak-check=full to see details of leaked memory
==4148834== 
==4148834== For lists of detected and suppressed errors, rerun with: -s
==4148834== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)
==4148834== could not unlink /tmp/vgdb-pipe-from-vgdb-to-4148834-by-root-on-???
==4148834== could not unlink /tmp/vgdb-pipe-to-vgdb-from-4148834-by-root-on-???
==4148834== could not unlink /tmp/vgdb-pipe-shared-mem-vgdb-4148834-by-root-on-???

[baranyaib90]

Hi, my first guess it, that libcurl causes this. I suggest to re-simulate internet outage, since it's quite easy. I will also try it out for myself later.

[baranyaib90]

I have found something similar :S The test I did: sending 1 successful request in with internet connection, than I cut the connection and I was sending in multiple requests. For valgrind it seems that curl was opening sockets, but it did not close them. (At the end of valgrind log: "FILE DESCRIPTORS: 11 open at exit." + a huge list.) Strange stuff is, that I have checked the socket open/close logs and it should be OK, but the socket numbers are rising instead of being reused. This might be a libcurl bug, but I don't know yet if it has been fixed in newer releases or not.

$ cat valgrind\ log\ of\ socket\ leak.txt | grep "curl.*socket: "
[D] 1623470169.826118 https_client.c:64 curl opened socket: 6
[D] 1623470200.748790 https_client.c:64 curl opened socket: 9
[D] 1623470200.763348 https_client.c:64 curl opened socket: 10
[D] 1623470200.777036 https_client.c:96 curl closed socket: 9
[D] 1623470200.791680 https_client.c:64 curl opened socket: 11
[D] 1623470200.813789 https_client.c:96 curl closed socket: 10
[D] 1623470200.821099 https_client.c:64 curl opened socket: 12
[D] 1623470200.833449 https_client.c:96 curl closed socket: 11
[D] 1623470200.846306 https_client.c:96 curl closed socket: 12
[D] 1623470201.009445 https_client.c:64 curl opened socket: 13
[D] 1623470201.015505 https_client.c:64 curl opened socket: 14
[D] 1623470201.018936 https_client.c:96 curl closed socket: 13
[D] 1623470201.021679 https_client.c:64 curl opened socket: 15
[D] 1623470201.030997 https_client.c:96 curl closed socket: 14
[D] 1623470201.034562 https_client.c:64 curl opened socket: 16
[D] 1623470201.037894 https_client.c:96 curl closed socket: 15
[D] 1623470201.048529 https_client.c:96 curl closed socket: 16
[D] 1623470221.321013 https_client.c:96 curl closed socket: 6

valgrind log of socket leak.txt

[baranyaib90]

I was not paying attention to the documentation description text (https://curl.se/libcurl/c/CURLOPT_CLOSESOCKETFUNCTION.html) And the example did not contain close() call on socket, so I have caused the socket leak. (Not libcurl.) Pull request with fix created. I think, that this won't affect so much users, since enabled statistic feature or debug logging is needed to call closesocket_callback function, which caused this.

[aarond10]

Thanks! Looks good!

On Sat, 12 Jun 2021, 2:38 pm baranyaib90, @.***> wrote:

I was not paying attention to the documentation description text ( https://curl.se/libcurl/c/CURLOPT_CLOSESOCKETFUNCTION.html) And the example did not contain close() call on socket, so I have caused the socket leak. (Not libcurl.) Pull request with fix created. I think, that this won't affect so much users, since enabled statistic feature or debug logging is needed to call closesocket_callback function, which caused this.

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/aarond10/https_dns_proxy/issues/118#issuecomment-859997039, or unsubscribe https://github.com/notifications/unsubscribe-auth/AABTOXTAODL5FZHSJP26JWDTSLQERANCNFSM46GQPOAQ .

[baranyaib90]

@aarond10 I guess this ticket could be closed because fix was merged.