Callback when server is unreachable

[FelicxFoster]

Simple server sends message to the client in the observer mode. I tried to close the server, then the client got WARN coap_network_read: unreachable in the terminal. How can I get the callback in my client code? Is there a special interface to get this callback? Thanks in advance

[mrdeep1]

Look at coap_handler(3) https://libcoap.net/doc/reference/4.2.1/man_coap_handler.html and try using coap_register_nack_handler() being called with a coap_nack_reason_t of COAP_NACK_ICMP_ISSUE.

It is possible that this may not trigger depending on what is actually happening and how your code is working.

[FelicxFoster]

Yup, I have read the issue [#249], and I have tried coap_register_nack_handler() before, but I cannot trigger it after I close my server. I only got the debug like this DEBG ** 127.0.0.1:38138 <-> 127.0.0.1:8754 UDP : tid=6549: delayed.

[mrdeep1]

Relying on ICMP diagnostic messages is problematic as these may be filtered out by firewalls etc. and different network stacks may behave differently. WARN coap_network_read: unreachable may be down to something else other than ICMP.

Have you tries using coap_context_set_keepalive() https://libcoap.net/doc/reference/4.2.1/man_coap_keepalive.html in the client (which works for UDP as well as DTLS)?

[FelicxFoster]

Yup, I have used coap_context_set_keepalive(ctx, 10) in the client, but it still couldn't trigger the coap_register_nack_handler() or the coap_register_ping_handler().

[mrdeep1]

As per coap_keepalive(3) documentation (no packets have been sent or received for a specified period), then if you have traffic occurring more frequently the keepalive will not trigger.

It would be good to see a packet capture of what is going on here to be able to better understand what is happening here.

[FelicxFoster]

I apologize for such a late reply. As a test case, I want the server sends data to the client in observer mode, and the client posts data in a coap request all the time. ★ First, I ran the server code, then ran the client, the coap log of client is as below.

Dec 07 18:59:12.269 DEBG *  [::1]:51134 <-> [::1]:8755 UDP : sent 76 bytes
v:1 t:CON c:POST i:30f9 {} [ Uri-Path:VehicleStatus ] :: '\x12"\x12 J\x09\xE4\xBA\xACAK8888b\x09\x09\x00\x00\x00\x00\x00Ps@\x91\x01\x00\x00\x00\x00\x00$\xA8@R\x12\x0A\x03(\xB5\x02\x12\x0B\x0A\x09\x19\x00\x00\x00\x00\x00$\xA8@'
Dec 07 18:59:12.269 DEBG ** [::1]:51134 <-> [::1]:8755 UDP : tid=12537: added to retransmit queue (2625ms)
Dec 07 18:59:12.269 DEBG *  [::1]:51134 <-> [::1]:8755 UDP : received 4 bytes
v:1 t:ACK c:0.00 i:30f9 {} [ ]
Dec 07 18:59:12.269 DEBG ** [::1]:51134 <-> [::1]:8755 UDP : tid=12537: removed
Dec 07 18:59:12.269 DEBG *  [::1]:51134 <-> [::1]:8755 UDP : received 105 bytes
v:1 t:NON c:2.05 i:2f03 {} [ ETag:\x5D\xAB\x39\xEA, Observe:307, Content-Format:text/plain, Max-Age:1 ] :: 'VehicleControl"3\x0A\x06\x10\xC8\x03(\xC8\x03\x12)\x18\xC8\x039\x00\x00\x00\x00\x00\x80|@b\x1B\x09\x00\x00\x00\x00\x00\x80|@\x11\x00\x00\x00\x00\x00\x80|@\x19\x00\x00\x00\x00\x00\x80|@j\x14\x0A\x08\x10\xA0\xE4\x02(\xA0\xE4\x02\x12\x08\x08\xA0\xE4\x02\x10\xA0\xE4\x02'

the coap log of server is as below.

Dec 08 09:24:18.360 DEBG *  [::1]:8755 <-> [::1]:32895 (if1) UDP : received 76 bytes
v:1 t:CON c:POST i:8300 {} [ Uri-Path:VehicleStatus ] :: '\x12"\x12 J\x09\xE4\xBA\xACAK8888b\x09\x09\x00\x00\x00\x00\x00\xA0p@\x91\x01\x00\x00\x00\x00\x00\xC8\xA4@R\x12\x0A\x03(\x8A\x02\x12\x0B\x0A\x09\x19\x00\x00\x00\x00\x00\xC8\xA4@'
Dec 08 09:24:18.360 DEBG call custom handler for resource 'VehicleStatus'
Dec 08 09:24:18.360 DEBG *  [::1]:8755 <-> [::1]:32895 (if1) UDP : sent 4 bytes
v:1 t:ACK c:0.00 i:8300 {} [ ]
Dec 08 09:24:18.360 DEBG *  [::1]:8755 <-> [::1]:32895 (if1) UDP : sent 105 bytes
v:1 t:CON c:2.05 i:bd77 {} [ ETag:\x1F\xA5\x8C\xAC, Observe:264, Content-Format:text/plain, Max-Age:1 ] :: 'VehicleControl"3\x0A\x06\x10\xE7\x02(\xE7\x02\x12)\x18\xE7\x029\x00\x00\x00\x00\x00pv@b\x1B\x09\x00\x00\x00\x00\x00pv@\x11\x00\x00\x00\x00\x00pv@\x19\x00\x00\x00\x00\x00pv@j\x14\x0A\x08\x10\xBC\x98\x02(\xBC\x98\x02\x12\x08\x08\xBC\x98\x02\x10\xBC\x98\x02'
Dec 08 09:24:18.361 DEBG ** [::1]:8755 <-> [::1]:32895 (if1) UDP : tid=48503: added to retransmit queue (2250ms)
Dec 08 09:24:18.361 DEBG *  [::1]:8755 <-> [::1]:32895 (if1) UDP : received 4 bytes
v:1 t:ACK c:0.00 i:bd77 {} [ ]
Dec 08 09:24:18.361 DEBG ** [::1]:8755 <-> [::1]:32895 (if1) UDP : tid=48503: removed

You can see, the client can post data normally(Uri-Path:VehicleStatus), and the client can get the server's data in observer mode(resource name:VehicleControl).

★ Second, I closed the sever, kept the client executing, the coap log of client is as below.

Dec 07 18:59:12.290 WARN coap_network_read: unreachable
Dec 07 18:59:12.290 DEBG ***[::1]:51134 <-> [::1]:8755 UDP : session disconnected (reason 4)
Dec 07 18:59:12.301 DEBG *  [::1]:51134 <-> [::1]:8755 UDP : sent 76 bytes
v:1 t:CON c:POST i:30fc {} [ Uri-Path:VehicleStatus ] :: '\x12"\x12 J\x09\xE4\xBA\xACAK8888b\x09\x09\x00\x00\x00\x00\x00\x80s@\x91\x01\x00\x00\x00\x00\x00`\xA8@R\x12\x0A\x03(\xB8\x02\x12\x0B\x0A\x09\x19\x00\x00\x00\x00\x00`\xA8@'
Dec 07 18:59:12.301 DEBG ** [::1]:51134 <-> [::1]:8755 UDP : tid=12540: added to retransmit queue (261ms)

★ In the end, I ran the server again, the coap log of client is as below.

Dec 08 08:52:30.338 DEBG *  [::1]:54258 <-> [::1]:8755 UDP : sent 76 bytes
v:1 t:CON c:POST i:4708 {} [ Uri-Path:VehicleStatus ] :: '\x12"\x12 J\x09\xE4\xBA\xACAK8888b\x09\x09\x00\x00\x00\x00\x00\x08\x80@\x91\x01\x00\x00\x00\x00\x00\x0A\xB4@R\x12\x0A\x03(\x81\x04\x12\x0B\x0A\x09\x19\x00\x00\x00\x00\x00\x0A\xB4@'
Dec 08 08:52:30.338 DEBG ** [::1]:54258 <-> [::1]:8755 UDP : tid=18184: added to retransmit queue (1085ms)
Dec 08 08:52:30.338 DEBG *  [::1]:54258 <-> [::1]:8755 UDP : received 4 bytes
v:1 t:ACK c:0.00 i:4708 {} [ ]
Dec 08 08:52:30.338 DEBG ** [::1]:54258 <-> [::1]:8755 UDP : tid=18184: removed

the coap log of server is as below.

Dec 08 09:27:31.464 DEBG *  [::1]:8755 <-> [::1]:45501 (if1) UDP : received 76 bytes
v:1 t:CON c:POST i:5721 {} [ Uri-Path:VehicleStatus ] :: '\x12"\x12 J\x09\xE4\xBA\xACAK8888b\x09\x09\x00\x00\x00\x00\x00p\x9A@\x91\x01\x00\x00\x00\x00\x00\x86\xD0@R\x12\x0A\x03(\x9C\x0D\x12\x0B\x0A\x09\x19\x00\x00\x00\x00\x00\x86\xD0@'
Dec 08 09:27:31.464 DEBG call custom handler for resource 'VehicleStatus'
Dec 08 09:27:31.464 DEBG *  [::1]:8755 <-> [::1]:45501 (if1) UDP : sent 4 bytes
v:1 t:ACK c:0.00 i:5721 {} [ ]

You can see, the server can only get the data posted by the client, but cannot send the data to the client in observer mode.

The reason I found that is, in the observer mode, the client needs to subscribe the same resource name(In my code is VehicleControl) use coap_add_option(). However, I only subscribe the name at the first initialization in my code. When I close the server, but my client still keep running, so subscribing the resource name has no longer effective. I only subscribe again can restore the receipt of data. So, I want to find the callback when the server will close, then I can subscribe the resource name again. Of course, I can also subscribe the resource name all the time, but It seems a little bit illogical, so I I'd like to ask about callback functions. hope to get your help, thx.

[mrdeep1]

Thanks for filling in more of the details about what you are trying to do. In particular, I had not realized you were using POST which makes more sense for the WARN coap_network_read: unreachable being reported.

v:1 t:CON c:POST i:8300 {} [ Uri-Path:VehicleStatus ] :: '\x12"\x12 J\x09\xE4\xBA\xACAK8888b\x09\x09\x00\x00\x00\x00\x00\xA0p@\x91\x01\x00\x00\x00\x00\x00\xC8\xA4@R\x12\x0A\x03(\x8A\x02\x12\x0B\x0A\x09\x19\x00\x00\x00\x00\x00\xC8\xA4@'
Dec 08 09:24:18.360 DEBG call custom handler for resource 'VehicleStatus'
Dec 08 09:24:18.360 DEBG *  [::1]:8755 <-> [::1]:32895 (if1) UDP : sent 4 bytes
v:1 t:ACK c:0.00 i:8300 {} [ ]

The t:ACK c:0.00 puzzles me. I would have expected a 2.01 or 2.04 piggybacked response or a 0.00 response followed fairly quick 2.01/2.04 response if using an separate (async) response. I suspect that you are not updating response->code in the POST handler when data is received.

Certainly when the server goes away and comes back again, the client will need to re-register the observe request. As the client is transmitting POST with CON, I would expected the POST transmission to eventually time out after 93 seconds (https://tools.ietf.org/html/rfc7252#section-4.8.2) - which then calls the nack handler with COAP_NACK_TOO_MANY_RETRIES.

PR #578 (not yet merged) now calls any defined nack handler with COAP_NACK_ICMP_ISSUE when coap_network_read: unreachable is reported.

As said previously, it is not safe to rely on ICMP packets getting back to the client for what you want to do. There is also a timing window where the server restarts between receiving a POST and receiving the next POST so no ICMP diagnostic packet is sent back, but the server now has no knowledge of any observer subscriptions and the client has not detected any issues.

The best way to fix what you are trying to do is for the client to take note of the Max-Age (Max-Age:1 in your case) and for the client to track when the last observe response was seen - and then determine that it has not seen a response for some time (> max age and probably > 93 seconds to handle a lossy network) and then re-register the observe request.

[mrdeep1]

#1019 now supports a tracking mechanism for Observes over a server restart.