weixin_39876645
weixin_39876645
2020-12-29 13:51

"Block2 transfer timed out" log message on successful blockwise exchange

Hi!

Faced with the issue while making a blockwise transfer:

The last chunk:


CON-PUT    MID=35441, Token=7d03f5e5b0, OptionSet={"Uri-Port":5000, "Uri-Path":["sys","fw"], "Block1":"(szx=5/512, m=false, num=64)"}, 
<hex skimmed>

ACK-2.04   MID=35441, Token=7d03f5e5b0, OptionSet={"Block1":"(szx=5/512, m=false, num=64)"}, no payload 
...
35 INFO [BlockwiseLayer$BlockCleanupTask]: Block2 transfer timed out: CON-PUT    MID=   -1, Token=null, OptionSet={"Uri-Port":5000, "Uri-Path":["sys","fw"]}, 
<hex skimmed>
 .. 32828 bytes - (org.eclipse.californium.core.network.stack.BlockwiseLayer$BlockCleanupTask.java:675) run() in thread pool-1-thread-4 at (2016-10-06 02:06:00)
</hex></hex>

The same time, CoapHandler#onSuccess was fired. All the chunks were OK. While debugging I saw at the client side of block transfer - there was a BlockCleanupTask scheduled but it was not cancelled. And BlockCleanupTask does not examine the corresponding Exchange time.

Unfortunately, I have lack of time right now so cannot craft a PR, but maybe I'll manage to do that. But I see two ways here: 1) Find out why the task is not being cancelled 2) Just check the exchange status at the BlockCleanupTask.

该提问来源于开源项目:eclipse/californium

  • 点赞
  • 写回答
  • 关注问题
  • 收藏
  • 复制链接分享
  • 邀请回答

10条回答

  • weixin_39856709 weixin_39856709 4月前

    ,

    is this still an issue? Otherwise I would like to close this issue ...

    点赞 评论 复制链接分享
  • weixin_39876645 weixin_39876645 4月前

    Oh, sorry, I had no chance to go further. Also I was not sure how to fix.

    Actually it is still there, the timeout log message is being printed anyway, was there a timout or not. This is not crucial at all just confusing.

    点赞 评论 复制链接分享
  • weixin_39856709 weixin_39856709 4月前

    Which version are you using?

    点赞 评论 复制链接分享
  • weixin_39876645 weixin_39876645 4月前

    1.0.4

    点赞 评论 复制链接分享
  • weixin_39856709 weixin_39856709 4月前

    Can you check if this is also occurring with 2.0.0 or a 1.1.0 nightly?

    点赞 评论 复制链接分享
  • weixin_39876645 weixin_39876645 4月前

    Sorry for delay, too much work. Tested against 2.0.0-M2, yes, it has an odd message:

    
    package blockwise_test;
    
    import org.eclipse.californium.core.CoapClient;
    import org.eclipse.californium.core.CoapResource;
    import org.eclipse.californium.core.CoapResponse;
    import org.eclipse.californium.core.CoapServer;
    import org.eclipse.californium.core.coap.CoAP;
    import org.eclipse.californium.core.network.config.NetworkConfig;
    import org.eclipse.californium.core.server.resources.CoapExchange;
    
    import java.util.Arrays;
    
    public class BlockwiseTimeoutTest {
        public static void main(String[] args) throws Exception {
            NetworkConfig.getStandard().set(NetworkConfig.Keys.BLOCKWISE_STATUS_LIFETIME, 1000);
            new CoapServer()
                    .add(
                            new CoapResource("block") {
    
                                public void handleGET(CoapExchange exchange) {
                                    byte b[] = new byte[10000];
                                    Arrays.fill(b, (byte) 0xFF);
                                    exchange.respond(CoAP.ResponseCode.VALID, b);
                                }
                            }
                    )
                    .start();
    
            Thread.sleep(500);
            new Thread(() -> {
                CoapClient client = new CoapClient("coap://lvh.me/block");
                CoapResponse resp = client.get();
                System.err.println("Got: " + resp.getPayload().length);
            }).start();
    
            System.in.read();
            System.exit(0);
        }
    }
    
    
    Dec 31, 2016 1:32:23 AM org.eclipse.californium.core.network.config.NetworkConfig createStandardWithFile
    INFO: Loading standard properties from file Californium.properties
    Dec 31, 2016 1:32:23 AM org.eclipse.californium.core.CoapServer start
    INFO: Starting server
    Dec 31, 2016 1:32:23 AM org.eclipse.californium.core.CoapServer start
    INFO: No endpoints have been defined for server, setting up server endpoint on default port 5,683
    Dec 31, 2016 1:32:23 AM org.eclipse.californium.core.network.CoapEndpoint start
    INFO: Starting endpoint at 0.0.0.0/0.0.0.0:5683
    Dec 31, 2016 1:32:24 AM org.eclipse.californium.core.network.CoapEndpoint start
    INFO: Starting endpoint at 0.0.0.0/0.0.0.0:0
    Dec 31, 2016 1:32:24 AM org.eclipse.californium.core.network.EndpointManager createDefaultEndpoint
    INFO: Created implicit default endpoint 0.0.0.0/0.0.0.0:59440
    Got: 10000
    Dec 31, 2016 1:32:25 AM org.eclipse.californium.core.network.stack.BlockwiseLayer$BlockCleanupTask run
    INFO: Block2 transfer timed out: {1}
    
    点赞 评论 复制链接分享
  • weixin_39876645 weixin_39876645 4月前

    Could not test against nightly build 1.1.0-20161219.173731-19 - did not receive any blockwise response for some reason

    点赞 评论 复制链接分享
  • weixin_39876645 weixin_39876645 4月前

    Current snapshot: 1.1.0-20170413.061056-43 Has the same issue:

    
     .. 512 bytes
    Got: 2048
    Apr 14, 2017 9:47:58 PM org.eclipse.californium.core.network.stack.BlockwiseLayer$BlockCleanupTask run
    INFO: Block2 transfer timed out: CON-GET    MID=26957, Token=22a71360c4d37fe9, OptionSet={"Uri-Host":"lvh.me", "Uri-Path":"block"}, no payload
    

    2.0.0-M4 and current 2.0.0-SNAPSHOT does not have such message at all, even in case of timeout (though it may be intended so).

    However, I've faced with another issue: #287. That is why I wasn't able to receive any blockwise response (see the previous message).

    点赞 评论 复制链接分享
  • weixin_39799307 weixin_39799307 4月前

    I tried to retest this issue. In my tests It occurs only on the client side, when still running the client a few seconds after a blockwise exchange. It writes a log message and completes a already completed exchange (should not harm too much). The 1.0.x and master (which is also the 1.1.x-nightly) are affected, but not the 2.0.x.

    My analysis of the root-cause: The blockwise layer doesn't cancel the cleanup when receiving the last response.

    Fix: Therefore I added that cancel to the ExchangeObserver.completed 1.0.x: 52597057ef3fb690861ea2a7ac8415ad31b24235 1.1.x(master): 633add41c0108b060a3baca6cf82397e3581e7b6

    If possible, it would be great, when you could also retest the issue.

    点赞 评论 复制链接分享
  • weixin_39876645 weixin_39876645 4月前

    I've just tested against the current 1.1.0-SNAPSHOT (1.1.0-20170511.122703-49) and 1.0.0-SNAPSHOT. Great, works well! Thanks!

    点赞 评论 复制链接分享

相关推荐