-
Notifications
You must be signed in to change notification settings - Fork 421
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
No retransmission for some block during block-wise transfer post #949
Comments
@jqiaobln Thanks for raising this. There are multiple things going on here that do not add up. It may help if you can send the whole log to me privately. Issue 1. How are you generating the tokens for the POST and subsequent GET request? Issue 2. The retransmit queue timeout times are not expected - e.g. 346ms, 11094ms and 250ms. I would be expecting these to be somewhere between 2000ms and 3000ms (ACK_TIMEOUT to ACK_TIMEOUT * ACK_RAMDOM_FACTOR as per RFC7252 Section 4.2 for the first transmit of a CON pdu. Are you modifying the ACK_TIMEOUT and/or ACK_RANDOM_FACTOR values ? What OS are you using? Does your host platform have a stable clock source? Issue 3. You report a response with mid of 0xc451, but have not provided the request that uses that mid. This response has a code of 2.01, so it is not a response to a GET. What was the request using mid 0xc451? Is this a broken server responding to request with mid 0xc44f with a mid of 0xc451? Issue 4. Where is the response to GET request with mid 0xc450 - is that missing as well? Other questions: Have you tried running your code using valgrind or similar to see if you are getting random memory corruptions? Have you tried running your client code against the libcoap examples coap-server to see if that highlights anything? Notes: |
@jqiaobln Do you have any further information to help get this resolved? |
|
@jqiaobln Thanks for this. If you could send me a copy of the full logs (at log level 7) privately, that would be helpful. Email address is in, for example, include/coap3/block.h as the second copyright entry. Do you know what version of CoAP code the server is running? |
Email sent. The server is using Eclipse Californium. |
Have you changed RFC7252 NSTART to 2 from 1? |
Yes |
Ok. Just trying to work out deviations from standard default values, but NSTART should not be an issue here. |
Thanks for the full logs. I will use abstracts here.
Several things to note here. As The difference between Each PDU created for transmission gets a unique message id - in the case of libcoap, this is monotonically incrementing, done by Looking at your log output, there is no creation for
Also for mid c451 and c452 the tokens in the response do not match any request. This implies to me for whatever reason the the 2 POST requests have not been logged - but somehow Are you using the same CoAP session when talking to hosts A and B? Is your client using libcoap as a single threaded, not multi-threaded (which is not safe) library? Can you send me privately the changes you made to libcoap, as well as the copy of coap-config.h you are using so I can try to track down why there is no logging (and possibly processing) for mid c451 and c452? Thanks. |
Are you able to shed any light on the entry Total: 255 bytes (with a short amount of actual data) and what it likely to be? It is at the point where there is the 2 missing mids.
|
The output can be stressed sometimes and miss a few lines.
I will usually check with server to make sure data is sent as expected.
|
Yes, it would be good to see the server side logs if you still have them for this issue - then I can fill in some of the missing output to see what the code is not correctly detecting the end of the transmission of a large body of data. I don;t think it is an issue here, but you appear to be randomizing just one byte of the token which has the potential to occasional have duplication of token for 2 requests and then get responses matching the wrong token (yes, mid also does de-duplication, but a non-piggybacked (separate) response will have different mids, but the same token.) |
As your client application is dropping some logging lines - is it possible that it is also dropping the lg_xmit deletion entry (and possibly the lg_crcv deletion entry)? It may be worth trying out out PR #948 (waiting to be merged) as this cleans up the lg_crcv promptly. As you have ACK_TIMEOUT set to 10 seconds instead of 2, then the initial retry if there is a packet loss will be somewhere between 10 and 15 seconds. On a lossy network waiting for retries, as the number of outstanding CON requests waiting for a response is limited to the NSTART value, a lot of transmissions potentially will get delayed. |
@jqiaobln Can you please try the latest develop branch code to see if you still have issues. |
Private update from @jqiaobln, providing the full logs with the comment
Thanks for this. Line 2134 is a duplicate response following the re-transmitted duplicate request at line 2049. libcoap handles duplicate responses at the start of The duplication response should also have been picked up in the I will look at getting a fix for this block logic issue. |
As a separate note, I am surprised to see the Size1 option in your detailed logs coming back from the server as per RFC7959 Section 4
Furthermore, it would be helpful to have the ETag option in the server's response as per RFC7959 Section 2.4 to make sure libcoap re-assembles the correct set of blocks.
|
I will give it a try ASAP. Do you recommend any other fixes I should merge as well?
|
The other fix would be #948 which is now merged into the develop branch. |
Hi Jon
I noticed when pdus time out during a block wise transfer and nack_handler is triggered, the token in the pdu will be the stateless token generated by libcoap internally. Is there an API which can be used to trace back to the original token?
Thanks
Juan
|
@jqiaobln This looks like a bug. There currently is no API to track back to the original token. I will look at getting a fix out for this, |
@jqiaobln Can this issue now be closed off? |
Environment
libcoap version (run
git describe --tags
to find it):4.3.1rc2
Build System: CMake
Operating System: Other
Operating System Version: [ ]
Hosted Environment: Other
Problem Description
Doing a post block-wise transfer. Block 0 was successfully transferred however block 1 didn't get ACK for more than 5 minutes.
Expected Behavior
libcoap should retry block 1 after a preset timeout, until the max number of retransmissions are run out.
Actual Behavior
No retransmission was sent.
Steps to reproduce
N/A
Code to reproduce this issue
N/A
Debug Logs
PDU presented by app.
v:1 t:CON c:POST i:c44e {fb2300d0} [ Content-Format:application/octet-stream ] :: binary data length 1488
** <-> UDP : lg_xmit 200a0d30 initialized
** <-> UDP : lg_crcv 200a0f40 initialized - stateless token xxxx0000dd2300d2
v:1 t:CON c:POST i:c44e {fb2300d0} [Content-Format:application/octet-stream, Block1:0/M/1024, Size1:1488, Request-Tag:0xacf445e6 ] :: binary data length 1024
** <-> UDP : mid=0xc44e: added to retransmit queue (346ms)
v:1 t:ACK c:2.31 i:c44e {fb2300d0} [ Block1:0/M/1024 ]
** <-> UDP : mid=0xc44e: removed 1
found Block option, block size is 1024, block nr. 0
v:1 t:CON c:POST i:c44f {020000dd2300d2} [ Content-Format:application/octet-stream, Block1:1/_/1024, Size1:1488, Request-Tag:0xacf445e6 ] :: binary data length 464
** <-> UDP : mid=0xc44f: added to retransmit queue (11094ms)
v:1 t:CON c:GET i:c450 {c72700d0} [ Content-Format:application/octet-stream, Block2:0/_/1024 ]
** <-> UDP : mid=0xc450: added to retransmit queue (250ms)
v:1 t:ACK c:2.01 i:c451 {5c2800d0} [ Content-Format:text/plain ] :: 'Successfully written'
** <-> UDP : mid=0xc451: removed 2
---------- No ACK nor retransmission for mid=0xc44f, No release for lg_xmit 200a0d30 and lg_crcv 200a0f40 ----------------
The text was updated successfully, but these errors were encountered: