Ponyc: UDP sockets stop listening after a while

[fweimer]

After some time (a few dozen days), my server stops listening on UDP sockets. lsof shows that the socket is just gone. This happens after a few weeks. I do not close the socket explicitly in my code. The server has very low utilization.

This happens on Debian 9 with a Git snapshot after 0.27 (commit 0d526e4da15f84b8760e7b3574b8d58e49466552 to be precise). It is not a recent regression; it happened before with older Pony versions.

[mfelsche]

Do you have any logs or metrics for your process? Which port did you listen on with which settings? Do you log anything in UDPNotify.closed?

[fweimer]

I do not see anything useful I could log in UDPNotify.closed, except for the timestamp when this happens. I have added logging for this event nevertheless.

I don't have any metrics, only packet captures of incoming and outgoing packets. I'm not sure what kind of metrics I could collect.

[mfelsche]

I was asking if you have any info if it was closed from within pony stdlib code or from the os somehow. If pony closed the socket somehow you should have been informed via your notify. In order to work around that issue for the time being you could reopen another socket if yours was closed. I am going to check for the possible conditions on which pony might close your socket.

[SeanTAllen]

@fweimer can you provide before and after lsof output?

[SeanTAllen]

@fweimer do you have a minimal program that demonstrates the problem?

[fweimer]

It happened again:

2019-05-16T15:19:56 info: TCP connection closed: 81.210.160.87/47071
2019-05-16T16:29:27 UDP socket closed
2019-05-17T06:00:18 info: incoming TCP connection from: 61.219.11.153/62616

So it appears spontaneous and not related to network activity (nothing else was logged around the time). The process was started at 2019-05-01T11:03:04, so the elapsed time is not a particularly round number.

lsof output before:

dns-serve 4381 root    0u      CHR   136,1      0t0      4 /dev/pts/1
dns-serve 4381 root    1u      CHR   136,1      0t0      4 /dev/pts/1
dns-serve 4381 root    2u      CHR   136,1      0t0      4 /dev/pts/1
dns-serve 4381 root    3u  a_inode    0,11        0   7518 [eventpoll]
dns-serve 4381 root    4u  a_inode    0,11        0   7518 [eventfd]
dns-serve 4381 root    5u      CHR     1,9      0t0   1042 /dev/urandom
dns-serve 4381 root    6u     IPv4 9451616      0t0    TCP *:domain (LISTEN)
dns-serve 4381 root    7u     IPv4 9450689      0t0    UDP *:domain 

And after:

dns-serve 4381 root    0u      CHR    136,1      0t0      4 /dev/pts/1
dns-serve 4381 root    1u      CHR    136,1      0t0      4 /dev/pts/1
dns-serve 4381 root    2u      CHR    136,1      0t0      4 /dev/pts/1
dns-serve 4381 root    3u  a_inode     0,11        0   7518 [eventpoll]
dns-serve 4381 root    4u  a_inode     0,11        0   7518 [eventfd]
dns-serve 4381 root    5u      CHR      1,9      0t0   1042 /dev/urandom
dns-serve 4381 root    6u     IPv4  9451616      0t0    TCP *:domain (LISTEN)
dns-serve 4381 root    8u     IPv4 12071872      0t0    TCP 159.69.214.55:domain->60.191.17.221:63489 (ESTABLISHED)

Observe the gap for file descriptor 7.

The last connection is a leftover from an earlier TCP-based query:

2019-05-14T06:10:23 info: incoming TCP connection from: 60.191.17.221/63489
2019-05-14T06:10:23 info: packet (30 bytes) from: 60.191.17.221/63489/TCP

Regarding a minimal reproducer, I guess I will try to reproduce with a minimal, idle server, given enough time.

[anacrolix]

Is it possible a write failing, triggering the UDPSocket to close? This can occur on some OS when under a lot of stress (Linux will do it, giving errors like EPERM). There seems to be no way to get the cause of failure for UDPSocket.writes.

[fweimer]

@anacrolix Sorry, I don't have access to Zulip. I guess a write or sendto failure is a possibility. Would this cause the socket go away, though?

[ergl]

Yes, if an error is raised while writing, the socket will be closed: https://github.com/ponylang/ponyc/blob/eb6fbbb16600249e1d90cd3e6674ebe75fecc5b0/packages/net/udp_socket.pony#L366-L370

https://github.com/ponylang/ponyc/blob/eb6fbbb16600249e1d90cd3e6674ebe75fecc5b0/packages/net/udp_socket.pony#L403-L408

[fweimer]

Hmm. This is rather awkward. Is it really necessary to close the socket here? It should be fairly easy to reproduce this with packets from a spoof source address to which no route exists in the routing table, assuming that the kernel does not implement IP reverse path filtering.

[SeanTAllen]

@fweimer do you have a minimal program that demonstrates the problem? it's very hard to know what might be an issue without being able to see code that can demonstrate it.

[fweimer]

I need to check if I still have the sources somewhere. (The application is more or less a basic UDP echo server, but it speaks DNS.) The issue reproduced only after a long time (several weeks). Close-on-error looks like the most likely culprit, though.

[aturley]

@fweimer were you able to find anything?