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 am in an all day workshop today L I will get back to this tonight …

 

Kai

 

From: cf-dev-bounces@xxxxxxxxxxx [mailto:cf-dev-bounces@xxxxxxxxxxx] On Behalf Of Kovatsch Matthias
Sent: Wednesday, November 18, 2015 11:27 PM
To: Californium (Cf) developer discussions
Subject: Re: [cf-dev] Contiki Erbium, Californium Proxy, Block2 transfer timed out

 

There is always something crossing plans :P

Anyhow, it’s done now after some delay.

 

Since the fix actually only affects a method that has not been used so far (at least no one noticed the quite stupid bug), I think we could go directly for 1.0.0, that is, no interim RC.

 

That would also be good, since Ian wants to publish the press release about the release tomorrow :)

 

I saw there is now also an all-in-one ZIP, but I would also like to have individual JAR downloads, in particular for the plugtest programs and tools. Would that work out with archiving the artifacts in the release-build jobs?

 

Ciao

Matthias

 

 

From: cf-dev-bounces@xxxxxxxxxxx [mailto:cf-dev-bounces@xxxxxxxxxxx] On Behalf Of Kovatsch Matthias
Sent: Wednesday, 18 November 2015 20:51
To: Californium (Cf) developer discussions <cf-dev@xxxxxxxxxxx>
Subject: Re: [cf-dev] Contiki Erbium, Californium Proxy, Block2 transfer timed out

 

Yes, I pushed the EndpointManager fix – hmm, we should update the HelloWorldServer so that it uses the call now… give me a moment.

 

From: cf-dev-bounces@xxxxxxxxxxx [mailto:cf-dev-bounces@xxxxxxxxxxx] On Behalf Of Hudalla Kai (INST/ESY)
Sent: Wednesday, 18 November 2015 17:50
To: Californium (Cf) developer discussions <cf-dev@xxxxxxxxxxx>
Subject: Re: [cf-dev] Contiki Erbium, Californium Proxy, Block2 transfer timed out

 

Does this mean that we are good to go for RC3? ;-)

 

Kai

 

From: cf-dev-bounces@xxxxxxxxxxx [mailto:cf-dev-bounces@xxxxxxxxxxx] On Behalf Of Kovatsch Matthias
Sent: Wednesday, November 18, 2015 5:37 PM
To: Californium (Cf) developer discussions
Subject: Re: [cf-dev] Contiki Erbium, Californium Proxy, Block2 transfer timed out

 

Okay, the proxy is really a mess… The CoAP-to-* functionality may not depend on a Uri-Path. We need a ProxyMessageDeliverer here that evaluates Proxy-Uri and Proxy-Scheme directly. Actually, I thought we had that once…

 

The main goal was to get the HTTP-to-CoAP functionality working for 1.0.0. I don’t think we can improve on the experimental state of the rest for 1.0.0.

 

Ciao

Matthias

 

 

 

From: cf-dev-bounces@xxxxxxxxxxx [mailto:cf-dev-bounces@xxxxxxxxxxx] On Behalf Of rahxepon12 .
Sent: Montag, 16. November 2015 16:18
To: Californium (Cf) developer discussions <cf-dev@xxxxxxxxxxx>
Subject: Re: [cf-dev] Contiki Erbium, Californium Proxy, Block2 transfer timed out

 

I only see 4 packets going from proxy to erbium in wireshark

 

 

Copper       Proxy       Erbium

   |---GET---->|           |

   |<---ACK----|           |

               |---GET---->|

               |<--Block#0-|

               |---GET#1-->|

               |<--Block#1-|

   |<--Block#0-|           | 

   |---GET#1-->|           |

               |---GET#1-->| [I don't see this packet in wireshark]

               |<--Block#1-|

   |<--Block#1-|           | 

 

 

It is even possible to not use block between Copper and proxy by setting block2 between copper and proxy.

But this still gives a time out.

 

Copper       Proxy       Erbium

   |---GET---->|           |

   |<---ACK----|           |

               |---GET---->|

               |<--Block#0-|

               |---GET#1-->|

               |<--Block#1-|

   |<----------|           |

   |----ACK--->|                     

 

On Mon, Nov 16, 2015 at 3:36 PM, Kovatsch Matthias <kovatsch@xxxxxxxxxxx> wrote:

I have an idea about the problem: Blockwise transfers use the Uri-Path to identify exchanges. When using the Proxy-Uri this might fail. Could you confirm the following:

 

Copper       Proxy       Erbium

   |---GET---->|           |

   |<---ACK----|           |

               |---GET---->|

               |<--Block#0-|

               |---GET#1-->|

               |<--Block#1-|

   |<--Block#0-|           | [see at bottom]

   |---GET#1-->|           |

               |---GET#1-->| [This is wrong and happens when the proxy

               |<--Block#1-|  does not find the previous exchange]

   |<--Block#1-|           | [This is a new exchange belonging to GET#1

                              and the “see at bottom” times out]

 

 

 

 

From: cf-dev-bounces@xxxxxxxxxxx [mailto:cf-dev-bounces@xxxxxxxxxxx] On Behalf Of rahxepon12 .
Sent: Montag, 16. November 2015 15:25


To: Californium (Cf) developer discussions <cf-dev@xxxxxxxxxxx>
Subject: 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

 

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);

                        }

}

 

But does it remove the task? I dont know much about runnable and tasks in java so i might be way off here..

 

protected void prepareBlockCleanup(Exchange exchange) {

                     

          // prevent RejectedExecutionException

          if (executor.isShutdown()) {

                      LOGGER.info("Endpoint is being destroyed: skipping block clean-up");

                      return;

          }

                     

          BlockCleanupTask task = new BlockCleanupTask(exchange);

                     

          ScheduledFuture<?> f = executor.schedule(task , block_timeout, TimeUnit.MILLISECONDS);

          exchange.setBlockCleanupHandle(f);

}

 

 

 

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

 


_______________________________________________
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