Check handling of ICMP errors in UDP mode

[nicolatimeus]

I noticed a possible issue if the library is configured to create an UDP channel to a host/port so that the host is reachable but the port is not bound by any process.
In this case it seems that the library closes and reopens the channel continuously, without any delay between two consecutive attempts regardless of the configured ChannelRetry.

I took a tcpdump capture on the machine running the library, the output is the following and repeats continuously:

08:26:03.927398 IP 192.168.1.4.20001 > 192.168.1.15.20001: UDP, length 17
08:26:03.929240 IP 192.168.1.15 > 192.168.1.4: ICMP 192.168.1.15 udp port 20001 unreachable, length 36
08:26:03.936501 IP 192.168.1.4.20001 > 192.168.1.15.20001: UDP, length 17
08:26:03.938731 IP 192.168.1.15 > 192.168.1.4: ICMP 192.168.1.15 udp port 20001 unreachable, length 36
08:26:03.946056 IP 192.168.1.4.20001 > 192.168.1.15.20001: UDP, length 17
08:26:03.956866 IP 192.168.1.15 > 192.168.1.4: ICMP 192.168.1.15 udp port 20001 unreachable, length 36
08:26:03.964693 IP 192.168.1.4.20001 > 192.168.1.15.20001: UDP, length 17
08:26:03.968120 IP 192.168.1.15 > 192.168.1.4: ICMP 192.168.1.15 udp port 20001 unreachable, length 36
08:26:03.975901 IP 192.168.1.4.20001 > 192.168.1.15.20001: UDP, length 17
08:26:03.977529 IP 192.168.1.15 > 192.168.1.4: ICMP 192.168.1.15 udp port 20001 unreachable, length 36
08:26:03.984591 IP 192.168.1.4.20001 > 192.168.1.15.20001: UDP, length 17
08:26:03.986223 IP 192.168.1.15 > 192.168.1.4: ICMP 192.168.1.15 udp port 20001 unreachable, length 36
08:26:03.993334 IP 192.168.1.4.20001 > 192.168.1.15.20001: UDP, length 17
08:26:03.994930 IP 192.168.1.15 > 192.168.1.4: ICMP 192.168.1.15 udp port 20001 unreachable, length 36
08:26:04.002017 IP 192.168.1.4.20001 > 192.168.1.15.20001: UDP, length 17

The machine running the library is 192.168.1.4, it seems that the issue is caused by the ICMP error sent back by the peer.
This causes an error on the channel side, as can be seen in the following log generated by the application using the library:

2020-10-21T08:18:54,102 [Thread-98] INFO   channel state changed to: OPEN
2020-10-21T08:18:54,109 [Thread-98] WARN   outstation stack: WARN Connection refused
2020-10-21T08:18:54,111 [Thread-98] INFO   channel state changed to: CLOSED
2020-10-21T08:18:54,113 [Thread-98] INFO   channel state changed to: OPENING
2020-10-21T08:18:54,116 [Thread-98] INFO   outstation stack: INFO Binding UDP socket to: 0.0.0.0, port 20001, resolving address: 192.168.1.15, port 20001
2020-10-21T08:18:54,119 [Thread-98] INFO   outstation stack: INFO UDP socket binded to: 0.0.0.0, port 20001, sending to 192.168.1.15, port 20001
2020-10-21T08:18:54,121 [Thread-98] INFO   channel state changed to: OPEN
2020-10-21T08:18:54,128 [Thread-98] WARN   outstation stack: WARN Connection refused
2020-10-21T08:18:54,130 [Thread-98] INFO   channel state changed to: CLOSED
2020-10-21T08:18:54,133 [Thread-98] INFO   channel state changed to: OPENING
2020-10-21T08:18:54,135 [Thread-98] INFO   outstation stack: INFO Binding UDP socket to: 0.0.0.0, port 20001, resolving address: 192.168.1.15, port 20001
2020-10-21T08:18:54,138 [Thread-98] INFO   outstation stack: INFO UDP socket binded to: 0.0.0.0, port 20001, sending to 192.168.1.15, port 20001
2020-10-21T08:18:54,140 [Thread-98] INFO   channel state changed to: OPEN
2020-10-21T08:18:54,147 [Thread-98] WARN   outstation stack: WARN Connection refused
2020-10-21T08:18:54,149 [Thread-98] INFO   channel state changed to: CLOSED
2020-10-21T08:18:54,151 [Thread-98] INFO   channel state changed to: OPENING
2020-10-21T08:18:54,154 [Thread-98] INFO   outstation stack: INFO Binding UDP socket to: 0.0.0.0, port 20001, resolving address: 192.168.1.15, port 20001
2020-10-21T08:18:54,157 [Thread-98] INFO   outstation stack: INFO UDP socket binded to: 0.0.0.0, port 20001, sending to 192.168.1.15, port 20001
2020-10-21T08:18:54,159 [Thread-98] INFO   channel state changed to: OPEN
2020-10-21T08:18:54,166 [Thread-98] WARN   outstation stack: WARN Connection refused
2020-10-21T08:18:54,168 [Thread-98] INFO   channel state changed to: CLOSED
2020-10-21T08:18:54,170 [Thread-98] INFO   channel state changed to: OPENING
2020-10-21T08:18:54,172 [Thread-98] INFO   outstation stack: INFO Binding UDP socket to: 0.0.0.0, port 20001, resolving address: 192.168.1.15, port 20001
2020-10-21T08:18:54,176 [Thread-98] INFO   outstation stack: INFO UDP socket binded to: 0.0.0.0, port 20001, sending to 192.168.1.15, port 20001
2020-10-21T08:18:54,178 [Thread-98] INFO   channel state changed to: OPEN
2020-10-21T08:18:54,185 [Thread-98] WARN   outstation stack: WARN Connection refused
2020-10-21T08:18:54,188 [Thread-98] INFO   channel state changed to: CLOSED
2020-10-21T08:18:54,190 [Thread-98] INFO   channel state changed to: OPENING
2020-10-21T08:18:54,192 [Thread-98] INFO   outstation stack: INFO Binding UDP socket to: 0.0.0.0, port 20001, resolving address: 192.168.1.15, port 20001
2020-10-21T08:18:54,196 [Thread-98] INFO   outstation stack: INFO UDP socket binded to: 0.0.0.0, port 20001, sending to 192.168.1.15, port 20001

This can cause log flooding and generates a lot of network traffic, which can be a serious issue on a metered connection.

The library is running on a Linux machine. I tried to use OSX, Linux and Windows machines as peer, the issue seems to occur in the first two cases but not in the latter.
Windows do not seem to send back ICMP errors.

I can think about the following strategies for fixing this:

• Using the UDP socket in unconnected mode, in this case at least on Linux the ICMP errors do not seem to be reported to the application by the OS, (even if the documentation is not so clear on this topic).
  I've created a commit that explores this approach at [1]. It seems to solve the issue at the cost of increased complexity and maybe worse performance.
• Change the code to ignore this specific error basing on error code. This can be tricky because if I understood correctly std::error_code is platform dependent.
• Configure the firewall on the master/outstation to drop incoming/outgoing ICMP error packets. This requires additional configuration on the machines and can lead to the loss of potentially interesting messages. This workaround should prevent the issue without the need for code changes.

Do you know any other possible ways to prevent this issue?

I observed this on 3.0.4 and release branch

[1] eurotech@151a0a8

[emgre]

Thanks for the detailed report!

We should honour the ChannelRetry::reconnectDelay on UDP sockets, but apparently, I forgot to add the required code when I did #366.

Can you try the bugfix/udp-connect-delay branch with a ChannelRetry::reconnectDelay set to a decent value and see if it fixes your issue?

[nicolatimeus]

Thank you for the quick answer, I tried something similar at first, it solved the log flooding and the excessive traffic problem, but I found I a remaining issue:
If you try to connect an opendnp3 master to an opendnp3 outstation over UDP the sockets on the two ends will stay bound for a very short time, making the connection difficult to establish, the following happened in my tests:

1. Host A binds the socket and sends the first datagram
2. The socket is likely not bound on host B (see 3), so it sends back an ICMP error message.
3. Host A closes the socket due to ICMP and waits for the reconnect delay to expire, during this interval the socket is not bound, so if B sends a datagram, it will get an ICMP error back.

This approach should work if one of the two ends keeps the socket bound all time.

[nicolatimeus]

Hi, do you have any update on this? Thanks

[jadamcrain]

We haven't had time to research it. It'll likely happen just before we need to implement UDP support for another project.

…

On Mon, Nov 23, 2020, 7:41 AM nicolatimeus ***@***.***> wrote: Hi, do you have any update on this? Thanks — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#405 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AACKVFKC5NKINBTAUBESWE3SRJ7C5ANCNFSM4S3MWIJQ> .