Skip to main content

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [cf-dev] Contiki Erbium, Californium Proxy, Block2 transfer timed out

I did some more testing and debugging. I set MAX_MESSAGE_SIZE to 16 and PREFERRED_BLOCK_SIZE to16.
Also changed BLOCKWISE_STATUS_LIFETIME to 30000 , so i get the message sooner.

I used a simple block transfer Get in Contiki

static void
res_get_handler(void *request, void *response, uint8_t *buffer, uint16_t preferred_size, int32_t *offset){
int32_t strpos = 0;
const char *msg = "abcdefghijklmnopqrstuvwxyz012345";
printf("offset1 = %d\n",*offset);
/* Check the offset for boundaries of the resource data. */
if(*offset >= 32) {
REST.set_response_status(response, REST.status.BAD_OPTION);
/* A block error message should not exceed the minimum block size (16). */
const char *error_msg = "BlockOutOfScope";
REST.set_response_payload(response, error_msg, strlen(error_msg));
return;
}

REST.set_response_payload(response, msg + *offset ,preferred_size);

/* IMPORTANT for chunk-wise resources: Signal chunk awareness to REST engine. */
*offset += preferred_size;
printf("offset2 = %d\n",*offset);
/* Signal end of resource representation. */
if(*offset >= strlen(msg)) {
*offset = -1;
}
}


Using Copper and node directly. Copper shows:
2.05 Content (Blockwise) (Download finished)
abcdefghijklmnopqrstuvwxyz012345

log from Copper:
INFO: Storing transaction 35405
=sending CoAP message===
 Type: Confirmable
 Code: GET
 Message ID: 35405
 Options:
  Uri-Path: wishful_control [15]
  Block2: 0/0/16 [0]
 =======================
-sent UDP datagram------
 Length: 22
 -----------------------
-receiving UDP datagram-
 Length: 24
 -----------------------
=received CoAP message==
 Type: Acknowledgment
 Code: 2.05 Content
 Message ID: 35405
 Options:
  Block2: 0/1/16 [1]
 Payload: 16 bytes
abcdefghijklmnop
 =======================
INFO: Closing message 35405
INFO: blockwiseHandler()
INFO: Storing transaction 35406
=sending CoAP message===
 Type: Confirmable
 Code: GET
 Message ID: 35406
 Options:
  Uri-Path: wishful_control [15]
  Block2: 1/0/16 [1]
 =======================
-sent UDP datagram------
 Length: 23
 -----------------------
-receiving UDP datagram-
 Length: 24
 -----------------------
=received CoAP message==
 Type: Acknowledgment
 Code: 2.05 Content
 Message ID: 35406
 Options:
  Block2: 1/0/16 [1]
 Payload: 16 bytes
qrstuvwxyz012345
 =======================
INFO: Closing message 35406
INFO: blockwiseHandler()

So Copper - node seems to work. I can't see anything wrong here.


Next with the proxy
===============

Copper shows:
2.05 Content (Blockwise) (Download finished)
abcdefghijklmnopqrstuvwxyz012345


Nov 16, 2015 2:42:59 PM org.eclipse.californium.proxy.resources.ProxyCoapClientResource forwardRequest
INFO: ProxyCoAP2CoAP forwards CON-GET    MID=61946, Token=, OptionSet={"Uri-Path":"coap2coap", "Content-Format":"text/plain", "Block2":"(szx=0/16, m=false, num=0)", "Proxy-Uri":"coap://[aaaa::c30c:0:0:2]:5683/wishful_control"}, no payload
Nov 16, 2015 2:42:59 PM org.eclipse.californium.proxy.resources.ProxyCoapClientResource forwardRequest
INFO: ProxyCoapClient received CoAP request and sends a copy to CoAP target
Nov 16, 2015 2:43:29 PM org.eclipse.californium.core.network.stack.BlockwiseLayer$BlockCleanupTask run
INFO: Block2 transfer timed out: CON-GET    MID=11716, Token=1135a2d2f9bd47c1, OptionSet={"Uri-Path":"wishful_control", "Content-Format":"text/plain"}, no payload


Copper Log 

INFO: Storing transaction 61946
=sending CoAP message===
 Type: Confirmable
 Code: GET
 Message ID: 61946
 Options:
  Uri-Path: coap2coap [9]
  Content-Format: 0 [0]
  Block2: 0/0/16 [0]
  Proxy-Uri: coap://[aaaa::c30c:0:0:2]:5683/wishful_control [46]
 =======================
-sent UDP datagram------
 Length: 64
 -----------------------
-receiving UDP datagram-
 Length: 4
 -----------------------
=received CoAP message==
 Type: Acknowledgment
 Code: EMPTY
 Message ID: 61946
 =======================
INFO: Closing message 61946
INFO: blockwiseHandler()
-receiving UDP datagram-
 Length: 24
 -----------------------
=received CoAP message==
 Type: Confirmable
 Code: 2.05 Content
 Message ID: 35020
 Options:
  Block2: 0/1/16 [1]
 Payload: 16 bytes
abcdefghijklmnop
 =======================
INFO: Incoming separate reponse (Token: null)
=sending CoAP message===
 Type: Acknowledgment
 Code: EMPTY
 Message ID: 35020
 =======================
-sent UDP datagram------
 Length: 4
 -----------------------
INFO: blockwiseHandler()
INFO: Storing transaction 61947
=sending CoAP message===
 Type: Confirmable
 Code: GET
 Message ID: 61947
 Options:
  Uri-Path: coap2coap [9]
  Content-Format: 0 [0]
  Block2: 1/0/16 [1]
  Proxy-Uri: coap://[aaaa::c30c:0:0:2]:5683/wishful_control [46]
 =======================
-sent UDP datagram------
 Length: 65
 -----------------------
-receiving UDP datagram-
 Length: 24
 -----------------------
=received CoAP message==
 Type: Acknowledgment
 Code: 2.05 Content
 Message ID: 61947
 Options:
  Block2: 1/0/16 [1]
 Payload: 16 bytes
qrstuvwxyz012345
 =======================
INFO: Closing message 61947
INFO: blockwiseHandler()


The payload is shown correctly in Copper. But after 30 secs the console of the proxy will show the time out message.
But everything works if you just look at the  output.


So i started debugging : org.eclipse.californium.core.network.stack.BlockwiseLayer 

The class that generates the time out output

protected class BlockCleanupTask implements Runnable {
private Exchange exchange;
public BlockCleanupTask(Exchange exchange) {
this.exchange = exchange;
}
@Override
public void run() {
if (exchange.getRequest()==null) {
LOGGER.info("Block1 transfer timed out: " + exchange.getCurrentRequest());
} else {
LOGGER.info("Block2 transfer timed out: " + exchange.getRequest());
}
exchange.setComplete();
}
}


I have 2 theories was that 

1) During the blockwise transfer there was a last message that was waiting for an ack or something.
Debugging in eclipse and wireshark i don't think that is the problem.. but i could have missed something



2) prepareBlockCleanup(exchange) is called when block transfer is used. Later when the exchange is complete the handler is set back to null.



public void sendResponse(Exchange exchange, Response response) {
   ....
   if (status.isComplete()) {
// clean up blockwise status
LOGGER.fine("Ongoing finished on first block "+status);
exchange.setResponseBlockStatus(null);
exchange.setBlockCleanupHandle(null);
                        }
}





To reproduce.
1) contiki 3.0
2) examples/er-rest-example
3) CoAP server with a resource that implements the get method above

4) cf-proxy coap2coap resource


On Mon, Nov 16, 2015 at 11:25 AM, Kovatsch Matthias <kovatsch@xxxxxxxxxxx> wrote:
The log message appears when a client did not get all blocks from a Californium server, in this case probably Copper getting the blocks from proxy.
Have you tried getting the blocks directly from the Erbium node?
Have you tried early and late negotiation with the proxy? You might test it with a payload smaller than the PREFERRED_BLOCK_SIZE, so that there is no Block2 between the proxy and Copper.

To learn more, I would need to run tests myself... might be a good idea before releasing the final 1.0.0 release.

Ciao
Matthias

> -----Original Message-----
> From: cf-dev-bounces@xxxxxxxxxxx [mailto:cf-dev-bounces@xxxxxxxxxxx] On
> Behalf Of Hudalla Kai (INST/ESY)
> Sent: Donnerstag, 12. November 2015 10:26
> To: Californium (Cf) developer discussions <cf-dev@xxxxxxxxxxx>
> Subject: Re: [cf-dev] Contiki Erbium, Californium Proxy, Block2 transfer timed
> out
>
> Hi Jo,
>
> personally, I am not very familiar with the Californium Proxy code and I am
> afraid that it is not as well maintained as e.g. Californium Core and Scandium
> :-(
>
> @Matthias: any ideas?
>
> Since your client code is C, you might also be able to get some help from the
> Wakaama community which does a lot of testing against leshan running on
> top of Californium.
>
> Sorry again,
> Kai
> ________________________________________
> Von: cf-dev-bounces@xxxxxxxxxxx [cf-dev-bounces@xxxxxxxxxxx]&quot; im
> Auftrag von &quot;rahxepon12 . [jdamme258@xxxxxxxxx]
> Gesendet: Montag, 9. November 2015 12:55
> An: cf-dev@xxxxxxxxxxx
> Betreff: [cf-dev] Contiki Erbium, Californium Proxy,    Block2 transfer timed
> out
>
> Hello,
>
> Im using the Contiki OS on some nodes.
> Because i need to do some translations between certain Content-Formats i
> want to use a californium proxy.
>
> For client software i'm using Copper.
>
> I use the example code for a blockwise transfer GET request from Contiki and
> the example proxy from californium.
>
> The data is correctly shown in Copper, but i get a time out message on the
> proxy.
>
> Nov 09, 2015 11:59:45 AM
> org.eclipse.californium.core.network.config.NetworkConfig
> createStandardWithFile
> INFO: Loading standard properties from file Californium.properties Nov 09,
> 2015 11:59:45 AM org.eclipse.californium.core.CoapServer start
> INFO: Starting server
> Nov 09, 2015 11:59:45 AM
> org.eclipse.californium.core.network.CoapEndpoint start
> INFO: Starting endpoint at 0.0.0.0/0.0.0.0:5683<http://0.0.0.0/0.0.0.0:5683>
> Nov 09, 2015 12:00:10 PM be.ugent.translator.Translator getRequest
> INFO: Forwarding request to coap://[aaaa::c30c:0:0:2]/wishful_control/
> Nov 09, 2015 12:00:10 PM
> org.eclipse.californium.core.network.CoapEndpoint start
> INFO: Starting endpoint at 0.0.0.0/0.0.0.0:0<http://0.0.0.0/0.0.0.0:0>
> Nov 09, 2015 12:00:10 PM
> org.eclipse.californium.core.network.EndpointManager
> createDefaultEndpoint
> INFO: Created implicit default endpoint
> 0.0.0.0/0.0.0.0:48414<http://0.0.0.0/0.0.0.0:48414>
> Nov 09, 2015 12:00:10 PM be.ugent.resource.ReverseResource
> forwardRequest
> INFO: Proxy received a Coap response.
> Nov 09, 2015 12:00:25 PM
> org.eclipse.californium.core.network.stack.BlockwiseLayer$BlockCleanupTas
> k run
> INFO: Block2 transfer timed out: CON-GET    MID=19113, Token=98a2ed,
> OptionSet={"Uri-Path":"wishful_control"}, no payload
>
>
>
>
> This is the console output from Copper :
>
>
> INFO: Storing transaction 48699
> =sending CoAP message===
>  Type: Confirmable
>  Code: GET
>  Message ID: 48699
>  Options:
>   Uri-Path: node2/wishful_control [21]
>  =======================
> -sent UDP datagram------
>  Length: 27
>  -----------------------
> -receiving UDP datagram-
>  Length: 4
>  -----------------------
> =received CoAP message==
>  Type: Acknowledgment
>  Code: EMPTY
>  Message ID: 48699
>  =======================
> INFO: Closing message 48699
> INFO: defaultHandler()
> -receiving UDP datagram-
>  Length: 37
>  -----------------------
> =received CoAP message==
>  Type: Confirmable
>  Code: 2.05 Content
>  Message ID: 20425
>  Payload: 32 bytes
> abcdefghijklmnopqrstuvwxyz012345
>  =======================
> INFO: Incoming separate reponse (Token: null) =sending CoAP message===
>  Type: Acknowledgment
>  Code: EMPTY
>  Message ID: 20425
>  =======================
> -sent UDP datagram------
>  Length: 4
>  -----------------------
> INFO: defaultHandler()
>
>
> The resource get_handler implementation :
>
> static void
> res_get_handler(void *request, void *response, uint8_t *buffer, uint16_t
> preferred_size, int32_t *offset){ const char *msg =
> "abcdefghijklmnopqrstuvwxyz012345";
> printf("offset1 = %d\n",*offset);
> /* Check the offset for boundaries of the resource data. */ if(*offset >= 32) {
> REST.set_response_status(response, REST.status.BAD_OPTION);
> /* A block error message should not exceed the minimum block size (16). */
> const char *error_msg = "BlockOutOfScope";
> REST.set_response_payload(response, error_msg, strlen(error_msg));
> return; }
>
> REST.set_response_payload(response, msg + *offset ,preferred_size);
>
> /* IMPORTANT for chunk-wise resources: Signal chunk awareness to REST
> engine. */ *offset += preferred_size;
> printf("offset2 = %d\n",*offset);
> /* Signal end of resource representation. */ if(*offset >= strlen(msg)) {
> *offset = -1; } }
>
> Output in Cooja :
>
> 34:43.394 ID:2 offset1 = 0
> 34:43.395 ID:2 offset2 = 16
> 34:44.273 ID:2 offset1 = 16
> 34:44.274 ID:2 offset2 = 32
>
>
> Anybody that can help me understand why there is a time out on the proxy?
>
> This is my idea :
>
>
> protected class BlockCleanupTask implements Runnable { private Exchange
> exchange; public BlockCleanupTask(Exchange exchange) { this.exchange =
> exchange; } @Override public void run() { if (exchange.getRequest()==null) {
> LOGGER.info("Block1 transfer timed out: " +
> exchange.getCurrentRequest()); } else {
> LOGGER.info("Block2 transfer timed out: " + exchange.getRequest()); }
> exchange.setComplete(); } }
>
>
> The blockwise tranfser is completed successfully ( cause the Copper client
> receives the data ), but the exchange is not closed?
> The problem is that i don't know if the issue is in Erbium or in Californium.
>
> Any thoughts would be greatly appreciated.
>
> Greets
>
> Jo
> _______________________________________________
> cf-dev mailing list
> cf-dev@xxxxxxxxxxx
> To change your delivery options, retrieve your password, or unsubscribe
> from this list, visit https://dev.eclipse.org/mailman/listinfo/cf-dev
_______________________________________________
cf-dev mailing list
cf-dev@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/cf-dev


Back to the top