coap-client gets stuck with large .well-known/core response

[anyc]

My CoAP server returns a large string for .well-known/core requests. When I request this resource with coap-client, it gets stuck and does not terminate. When I request this with my own client, I get the complete response. The following logs are from different runs, so the numbers will not match, sorry. I just noticed when I finished writing this report.

The coap-client output:

Jul 16 17:12:53.176 DEBG ***[fe80::4dd8:5d0a:e344:f549]:60440 <-> [fe80::20f:69ff:feff:d6c4]:5684 DTLS: session connected
Jul 16 17:12:53.176 DEBG ** [fe80::4dd8:5d0a:e344:f549]:60440 <-> [fe80::20f:69ff:feff:d6c4]:5684 DTLS: mid=0x83c3: transmitted after delay
Jul 16 17:12:53.176 DEBG *  [fe80::4dd8:5d0a:e344:f549]:60440 <-> [fe80::20f:69ff:feff:d6c4]:5684 DTLS: netif: sent   58 bytes
Jul 16 17:12:53.176 DEBG *  [fe80::4dd8:5d0a:e344:f549]:60440 <-> [fe80::20f:69ff:feff:d6c4]:5684 DTLS: dtls:  sent   29 bytes
v:1 t:CON c:GET i:83c3 {01} [ Uri-Path:.well-known, Uri-Path:core, Request-Tag:0xbe37b96f ]
Jul 16 17:12:53.176 DEBG ** [fe80::4dd8:5d0a:e344:f549]:60440 <-> [fe80::20f:69ff:feff:d6c4]:5684 DTLS: mid=0x83c3: added to retransmit queue (2969ms)
Jul 16 17:12:53.178 DEBG *  [fe80::4dd8:5d0a:e344:f549]:60440 <-> [fe80::20f:69ff:feff:d6c4]:5684 DTLS: netif: recv   33 bytes
v:1 t:ACK c:0.00 i:83c3 {} [ ]
Jul 16 17:12:53.178 DEBG ** [fe80::4dd8:5d0a:e344:f549]:60440 <-> [fe80::20f:69ff:feff:d6c4]:5684 DTLS: mid=0x83c3: removed (1)
Jul 16 17:12:53.180 DEBG *  [fe80::4dd8:5d0a:e344:f549]:60440 <-> [fe80::20f:69ff:feff:d6c4]:5684 DTLS: netif: recv 1068 bytes
v:1 t:CON c:2.05 i:7a9d {01} [ ETag:0x01, Content-Format:application/link-format, Block2:0/M/1024, Size2:6302 ] :: ' --shortened--
Jul 16 17:12:53.180 DEBG ** [fe80::4dd8:5d0a:e344:f549]:60440 <-> [fe80::20f:69ff:feff:d6c4]:5684 DTLS: large body receive internal issue
Jul 16 17:12:53.180 DEBG *  [fe80::4dd8:5d0a:e344:f549]:60440 <-> [fe80::20f:69ff:feff:d6c4]:5684 DTLS: netif: sent   33 bytes
Jul 16 17:12:53.180 DEBG *  [fe80::4dd8:5d0a:e344:f549]:60440 <-> [fe80::20f:69ff:feff:d6c4]:5684 DTLS: dtls:  sent    4 bytes
v:1 t:ACK c:0.00 i:7a9d {} [ ]

The server output with coap-client:

Apr 28 18:38:24.491 DEBG ** [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:55061 (if8) DTLS: lg_xmit 0x4e1878 initialized
Apr 28 18:38:24.491 DEBG *  [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:55061 (if8) DTLS: netif: sent 1068 bytes
Apr 28 18:38:24.492 DEBG *  [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:55061 (if8) DTLS: dtls:  sent 1039 bytes
v:1 t:CON c:2.05 i:05cd {01} [ ETag:0x01, Content-Format:application/link-format, Block2:0/M/1024, Size2:6302 ] :: --shortened--
Apr 28 18:38:24.492 DEBG ** [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:55061 (if8) DTLS: mid=0x05cd: added to retransmit queue (2250ms)
Apr 28 18:38:24.492 DEBG *  [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:55061 (if8) DTLS: netif: recv   33 bytes
v:1 t:ACK c:0.00 i:05cd {} [ ]
Apr 28 18:38:24.493 DEBG ** [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:55061 (if8) DTLS: mid=0x05cd: removed (1)

and no further communication after the last line.

With my client:

Apr 28 18:39:02.437 DEBG ** [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:56484 (if8) DTLS: lg_xmit 0x561cf0 initialized
Apr 28 18:39:02.438 DEBG *  [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:56484 (if8) DTLS: netif: sent 1069 bytes
Apr 28 18:39:02.438 DEBG *  [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:56484 (if8) DTLS: dtls:  sent 1040 bytes
v:1 t:CON c:2.05 i:0750 {96b1} [ ETag:0x01, Content-Format:application/link-format, Block2:0/M/1024, Size2:6302 ] :: --shortened--
Apr 28 18:39:02.438 DEBG ** [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:56484 (if8) DTLS: mid=0x0750: added to retransmit queue (2938ms)
Apr 28 18:39:02.438 DEBG *  [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:56484 (if8) DTLS: netif: recv   33 bytes
v:1 t:ACK c:0.00 i:0750 {} [ ]
Apr 28 18:39:02.438 DEBG ** [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:56484 (if8) DTLS: mid=0x0750: removed (1)
Apr 28 18:39:02.439 DEBG *  [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:56484 (if8) DTLS: netif: recv   54 bytes
v:1 t:CON c:GET i:9c32 {96b2} [ Uri-Path:.well-known, Uri-Path:core, Block2:1/_/1024 ]
Apr 28 18:39:02.439 DEBG found Block option, block size is 1024, block nr. 1, M 0
Apr 28 18:39:02.439 DEBG *  [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:56484 (if8) DTLS: netif: sent 1069 bytes
Apr 28 18:39:02.439 DEBG *  [fe80::20f:69ff:feff:d6c4]:5684 <-> [fe80::4dd8:5d0a:e344:f549]:56484 (if8) DTLS: dtls:  sent 1040 bytes

and more lines after that.

This happens with current develop branch and with my last PR commit 782e607.

This is not a problem for me, I just noticed this by accident.

[mrdeep1]

Thanks for raising this. DTLS: large body receive internal issue is where things are not working. I will look into this. Are you using the -L option for the coap-client (i.e. setting COAP_BLOCK_SINGLE_BODY)?

[mrdeep1]

I'm not able to reproduce this with a 6302 byte long response using latest develop code 7551d2e for coaps using PSK.

Jul 16 22:13:12.379 DEBG ***EVENT: COAP_EVENT_DTLS_CONNECTED
Jul 16 22:13:12.379 DEBG ***127.0.0.1:37621 <-> 127.0.0.1:5684 DTLS: session connected
Jul 16 22:13:12.379 DEBG ** 127.0.0.1:37621 <-> 127.0.0.1:5684 DTLS: mid=0x80c3: transmitted after delay
Jul 16 22:13:12.379 DEBG *  127.0.0.1:37621 <-> 127.0.0.1:5684 DTLS: netif: sent   57 bytes
Jul 16 22:13:12.379 DEBG *  127.0.0.1:37621 <-> 127.0.0.1:5684 DTLS: dtls:  sent   28 bytes
v:1 t:CON c:GET i:80c3 {} [ Uri-Path:.well-known, Uri-Path:core, Request-Tag:0x75003918 ]
Jul 16 22:13:12.379 DEBG ** 127.0.0.1:37621 <-> 127.0.0.1:5684 DTLS: mid=0x80c3: added to retransmit queue (2188ms)
Jul 16 22:13:12.379 DEBG ****** Next wakeup time   2.188000000
Jul 16 22:13:12.379 DEBG ****** Next wakeup time   2.188000000
Jul 16 22:13:12.380 DEBG ****** Next wakeup time   2.187000000
Jul 16 22:13:12.380 DEBG *  127.0.0.1:37621 <-> 127.0.0.1:5684 DTLS: netif: recv 1067 bytes
v:1 t:ACK c:2.05 i:80c3 {} [ ETag:0x07, Content-Format:application/link-format, Block2:0/M/1024, Size2:6302 ] :: '--data stripped 
Jul 16 22:13:12.380 DEBG ** 127.0.0.1:37621 <-> 127.0.0.1:5684 DTLS: mid=0x80c3: removed (1)
Jul 16 22:13:12.380 DEBG ** 127.0.0.1:37621 <-> 127.0.0.1:5684 DTLS: lg_crcv 0x5603bb287110 initialized - stateless token xxxx000000000001
Jul 16 22:13:12.380 DEBG found Block option, block size is 1024, block nr. 0
Jul 16 22:13:12.380 DEBG *  127.0.0.1:37621 <-> 127.0.0.1:5684 DTLS: netif: sent   66 bytes
Jul 16 22:13:12.380 DEBG *  127.0.0.1:37621 <-> 127.0.0.1:5684 DTLS: dtls:  sent   37 bytes
v:1 t:CON c:GET i:80c4 {02000000000001} [ Uri-Path:.well-known, Uri-Path:core, Block2:1/_/1024, Request-Tag:0x75003918 ]
Jul 16 22:13:12.381 DEBG ** 127.0.0.1:37621 <-> 127.0.0.1:5684 DTLS: mid=0x80c4: added to retransmit queue (2344ms)
Jul 16 22:13:12.381 DEBG ****** Next wakeup time   2.344000000
Jul 16 22:13:12.381 DEBG ****** Next wakeup time   2.344000000
Jul 16 22:13:12.381 DEBG *  127.0.0.1:37621 <-> 127.0.0.1:5684 DTLS: netif: recv 1074 bytes

Were you using code from #1469 - I did find a late fix this which could explain what you are seeing.

[anyc]

Sorry, my mistake. I accidentally used the system coap-client not the one I built from the repo. With the one from the develop branch it works as expected. Thank you!