Multiblock GET request with Etag incorrectly invokes handler twice for COAP_BLOCK_SINGLE_BODY

[cdurkin]

Environment

• Build System: Eclipse / MCUXpresso
• Operating System: Windows 11
• Hosted Environment: LwIP, FreeRTOS

libcoap Configuration Summary

libcoap package version : "4.3.5"
libcoap package source : "4.3.5"
libcoap API version : "3"
libcoap ABI version : "3.2.0"
libcoap libtool SO version : "5.0.2"
libcoap DTLS lib extn : "-mbedtls"
host system : "x86_64-pc-linux-gnu"
build with server support : "yes"
build with client support : "yes"
build with proxy support : "yes"
build with IPv4 support : "yes"
build with IPv6 support : "yes"
build with Unix socket support : "yes"
build with TCP support : "yes"
build DTLS support : "yes"
--> Mbed TLS around : "yes" (found Mbed TLS without pkg-config)
MbedTLS_CFLAGS : ""
MbedTLS_LIBS : ""
build DTLS support : "no"
add default names : "yes"
build Observe Persist : "yes"
build using epoll : "yes"
enable small stack size : "no"
enable separate responses : "yes"
enable OSCORE support : "yes"
enable Q-Block support : "yes"
enable max logging level : "none"
enable thread safe code : "yes"
enable recursive lock check : "yes"
build doxygen pages : "no"
build man pages : "no"
build unit test binary : "no"
build examples : "yes"
install examples source : "yes"
build with gcov support : "no"
build shared library : "yes"
build static library : "yes"

Problem Description

Performing a GET for a large resource (i.e. one that triggers a multiblock response) that includes an Etag causes the GET handler to be invoked twice causing the 2nd block in the response to be missing the Etag.

The logs include warnings: "dbg: ***EVENT: COAP_EVENT_XMIT_BLOCK_FAIL" and "Warn: Not all blocks have ETag option"

Expected Behavior

My test to pass, my GET_Handler to only be invoked once regardless of whether the GET request in includes an Etag or not.

Code to reproduce this issue

I'm working on a embedded device using FreeRTOS where we have one task for the CoAP client and one for the CoAP server. The server sets block mode i.e.

coap_context_set_block_mode(coap_context, COAP_BLOCK_USE_LIBCOAP | COAP_BLOCK_SINGLE_BODY);

When we create resource we set them as observerable (doubt this matters but it just in case) and set GET and PUT handlers i.e.

r = coap_resource_init(	s, COAP_RESOURCE_FLAGS_RELEASE_URI );
coap_resource_set_get_observable(r, 1);
coap_add_resource(coap_server_context, r);
coap_register_handler(r, COAP_REQUEST_GET, GET_Callback);
coap_register_handler(r, COAP_REQUEST_PUT, PUT_Callback);

My GET handler

void GET_Callback(	coap_resource_t *resource,
				coap_session_t *session,
				const coap_pdu_t *request,
				const coap_string_t *query,
				coap_pdu_t *response)
{
    // get etag from request
    uint64_t etag = /* ... */

    // check if etag in request matches resource's etag
    if (pstResource->u64Etag == etag) {
        // add etag and max age option to response
        // ....

        response->code = COAP_RESPONSE_CODE(203);
        return;
    }

    // create payload
    void * pvData = /* ... */
    size_t uiLen = /* ... */

    // add payload to response
    coap_add_data_large_response(
		resource,
		session,
		request,
		response,
		query,
		pstResource->ui16MediaType,
		pstResource->iMaxAge,
		pstResource->u64Etag,
		uiLen,
		pvData,
		NULL,
		NULL);
}

Debug Logs

~~~~~~~~~~~~~~~~~~~~  Tests Start  ~~~~~~~~~~~~~~~~~~~~
Run: filter 'GET Multiblock Non'
--- Running set: CoAP
Running test 1: GET Multiblock Non-Matching Etag
Jan 01 00:06:03.943 dbg : Alloc type: 24, in use 2
Jan 01 00:06:03.067 dbg : ***[192.168.50.1]:60595 <-> [192.168.50.1]:5683 UDP : session 0x80012a80: created outgoing session
Jan 01 00:06:03.116 dbg : ***[192.168.50.1]:60595 <-> [192.168.50.1]:5683 UDP : session connected
Jan 01 00:06:03.157 dbg : ***[192.168.50.1]:60595 <-> [192.168.50.1]:5683 UDP : session max_retransmit set to 1
Jan 01 00:06:03.616 dbg : Alloc type: 24, in use 3
Jan 01 00:06:03.706 dbg : ***[192.168.50.1]:5683 <-> [192.168.50.1]:60595 (if2) UDP : session 0x800138c8: new incoming session
Jan 01 00:06:03.738 dbg : ***EVENT: COAP_EVENT_SERVER_SESSION_NEW
v:1 t:CON c:GET i:f42e {} [ ETag:0x0000256200000002, Uri-Path:datatest, Uri-Path:container, Content-Format:application/json, 18:, 22:\x23\x54\x65\x73\x74, Request-Tag:0x40b18cd0 ]

Jan 01 00:06:03.119 dbg : call custom handler for resource 'datatest/container' (3)
Jan 01 00:06:03.773 dbg : PDU presented by app.
v:1 t:ACK c:2.05 i:f42e {} [ Content-Format:application/json, 18:, 22:\x23\x54\x65\x73\x74 ] :: '{"Step Inputs":false,"Inputx1":{"InputType":"Single Input","State":0,"Quality":0,"Timestamp":{"secs":0,"nsecs":0,"timequality":0}},"Inputx2":{"Inp

Jan 01 00:06:03.893 dbg : ** [192.168.50.1]:5683 <-> [192.168.50.1]:60595 (if2) UDP : lg_xmit 0x80014828 initialized
Jan 01 00:06:03.354 dbg : *  [192.168.50.1]:60595 <-> [192.168.50.1]:5683 UDP : netif: sent   48 bytes
v:1 t:CON c:GET i:f42e {} [ ETag:0x0000256200000002, Uri-Path:datatest, Uri-Path:container, Content-Format:application/json, 18:, 22:\x23\x54\x65\x73\x74, Request-Tag:0x40b18cd0 ]

Jan 01 00:06:03.510 dbg : ** [192.168.50.1]:60595 <-> [192.168.50.1]:5683 UDP : mid=0xf42e: added to retransmit queue (2281ms)
v:1 t:ACK c:2.05 i:f42e {} [ ETag:0x256200000001, Content-Format:application/json, 18:, 22:\x23\x54\x65\x73\x74, Block2:0/M/1024, Size2:1999 ] :: '{"Step Inputs":false,"Inputx1":{"InputType":"Single Input","State":0,"Quality":0,"Timestamp":{"s

Jan 01 00:06:03.710 dbg : ** [192.168.50.1]:60595 <-> [192.168.50.1]:5683 UDP : mid=0xf42e: removed (1)
Jan 01 00:06:03.808 dbg : ** [192.168.50.1]:60595 <-> [192.168.50.1]:5683 UDP : lg_crcv 0x800151e0 initialized - stateless token xxxx000000000001
Jan 01 00:06:03.915 dbg : found Block option, block size is 1024, block nr. 0
Jan 01 00:06:03.256 dbg : *  [192.168.50.1]:5683 <-> [192.168.50.1]:60595 (if2) UDP : netif: sent 1050 bytes
v:1 t:ACK c:2.05 i:f42e {} [ ETag:0x256200000001, Content-Format:application/json, 18:, 22:\x23\x54\x65\x73\x74, Block2:0/M/1024, Size2:1999 ] :: '{"Step Inputs":false,"Inputx1":{"InputType":"Single Input","State":0,"Quality":0,"Timestamp":{"s

v:1 t:CON c:GET i:f42f {02000000000001} [ ETag:0x0000256200000002, Uri-Path:datatest, Uri-Path:container, Content-Format:application/json, 18:, 22:\x23\x54\x65\x73\x74, Block2:1/_/1024, Request-Tag:0x40b18cd0 ]

Jan 01 00:06:03.685 dbg : call custom handler for resource 'datatest/container' (3)
Jan 01 00:06:03.848 dbg : ** [192.168.50.1]:5683 <-> [192.168.50.1]:60595 (if2) UDP : lg_xmit 0x80014828 released
Jan 01 00:06:03.884 dbg : ***EVENT: COAP_EVENT_XMIT_BLOCK_FAIL
Jan 01 00:06:03.243 dbg : *  [192.168.50.1]:60595 <-> [192.168.50.1]:5683 UDP : netif: sent   57 bytes
v:1 t:CON c:GET i:f42f {02000000000001} [ ETag:0x0000256200000002, Uri-Path:datatest, Uri-Path:container, Content-Format:application/json, 18:, 22:\x23\x54\x65\x73\x74, Block2:1/_/1024, Request-Tag:0x40b18cd0 ]

Jan 01 00:06:03.425 dbg : ** [192.168.50.1]:60595 <-> [192.168.50.1]:5683 UDP : mid=0xf42f: added to retransmit queue (2156ms)
v:1 t:ACK c:2.05 i:f42f {02000000000001} [ Content-Format:application/json, 18:, 22:\x23\x54\x65\x73\x74, Block2:1/_/1024 ] :: '00,"RangeMax":0.000000,"Quality":0,"Timestamp":{"secs":0,"nsecs":0,"timequality":0}},"Counterx2":{"InputType":"Doub

Jan 01 00:06:03.611 dbg : ** [192.168.50.1]:60595 <-> [192.168.50.1]:5683 UDP : mid=0xf42f: removed (1)
Jan 01 00:06:03.690 Warn: Not all blocks have ETag option
Jan 01 00:06:03.737 dbg : Client app version of updated PDU (3)
v:1 t:ACK c:2.05 i:f42f {} [ Content-Format:application/json, 18:, 22:\x23\x54\x65\x73\x74, Block2:1/_/1024 ] :: '00,"RangeMax":0.000000,"Quality":0,"Timestamp":{"secs":0,"nsecs":0,"timequality":0}},"Counterx2":{"InputType":"Double Counter","S

Jan 01 00:06:03.939 dbg : *  [192.168.50.1]:5683 <-> [192.168.50.1]:60595 (if2) UDP : netif: sent  998 bytes
v:1 t:ACK c:2.05 i:f42f {02000000000001} [ Content-Format:application/json, 18:, 22:\x23\x54\x65\x73\x74, Block2:1/_/1024 ] :: '00,"RangeMax":0.000000,"Quality":0,"Timestamp":{"secs":0,"nsecs":0,"timequality":0}},"Counterx2":{"InputType":"Doub

Jan 01 00:06:03.251 dbg : ** [192.168.50.1]:60595 <-> [192.168.50.1]:5683 UDP : lg_crcv 0x800151e0 released
Jan 01 00:06:03.320 dbg : ***[192.168.50.1]:60595 <-> [192.168.50.1]:5683 UDP : session 0x80012a80: closed
Jan 01 00:06:03.346 dbg : Free type: 24, in use 2
../../Plugin_DataTest/tests/coap_tests.c:761:GET Multiblock Non-Matching Etag:FAIL: Expected 0x0000256200000001 Was 0x0000000000000000.

Other info

So I've investigated and traced this down to line 2479 of coap_block.c,

  /* lg_xmit (response) found */

  etag_opt = coap_check_option(pdu, COAP_OPTION_ETAG, &opt_iter);
  if (etag_opt) {
    uint64_t etag = coap_decode_var_bytes8(coap_opt_value(etag_opt),
                                           coap_opt_length(etag_opt));
    if (etag != lg_xmit->b.b2.etag) {
      /* Not a match - pass up to a higher level */
      return 0;
    }
    out_pdu->code = COAP_RESPONSE_CODE(203);
    coap_ticks(&lg_xmit->last_sent);
    goto skip_app_handler;
  } else {
    out_pdu->code = lg_xmit->pdu.code;
  }

The fact the request has an etag is triggering this if() and because the etags don't match the code hits line 2484 causing the GET handler to be called gain despite the fact we don't want it to because block mode is COAP_BLOCK_USE_LIBCOAP | COAP_BLOCK_SINGLE_BODY and surely because the etags don't match hence we do want to include the payload in the response?

I've worked around this issue by simply commented out line 2478 so etag_opt remains NULL and the if() is not triggered but obviously this is not a correct fix.

This code looks like it should be doing the appropriate check if the etags match and setting response code 2.03 but this code only invokes during block transfer. As shown above I've added code in my GET Handler to check if the etags match and return 2.03 (i.e. so this handles all cases regardless of whether the response is multiblock or not).

Please let me know if libcoap handles the checking of etags and responding with 2.03 but i didn't notice this in the documentation.

Thanks
Chris

[mrdeep1]

Thanks for raising this. I am able to reproduce the issue and will look at creating a fix.

The example server code does not track responses and Etags so does not generate a 2.03 response. However, adding in code in the server application handler such as you have done will cause 2.03 responses to be generated when appropriate as you are tracking the Etag in pstResource.

[mrdeep1]

@cdurkin Please checkout out #1545 which I believe fixes your issue.

Please let me know if libcoap handles the checking of etags and responding with 2.03

#1545 now does this in the libcoap library. However, for the server, if coap_add_data() is used instead of coap_add_data_large_response(), an ETag option (computed using the internal coap_digest_*() functions) will not get added, so it is recommended that you use coap_add_data_large_response() even though the amount of data may be small.

[cdurkin]

Thanks very much, i'll give this a test hopefully early this coming week and report back.

Assuming no further issues, when do you think you'll do the next release that will include this fix, as I'd rather update our product to a tagged release of libcoap then just this commit.

[mrdeep1]

There are no immediate plans for the next tagged release of libcoap. I certainly would like to give this fix some airtime before doing a tag (it has had lots of testing, but .....).

If you cherry pick this fix on top of 4.3.5, you will also need to include #1543.

[cdurkin]

Apologies only just got to testing this but all looks good, thanks very much :)

[mrdeep1]

Thanks for the confirmation. I will close this now.