[
Date Prev][
Date Next][
Thread Prev][
Thread Next][
Date Index][
Thread Index]
[
List Home]
|
[cf-dev] RE : RE : Clean-up mechanism for blockwise transfer is removing observe state
|
Hi Matthias,
Observe is working OK over long period of time if there is no block2 option involves in the observe response.
I have extracted more logs but I still cannot explain what is going on.
{log from californium}
Dec 22, 2015 3:14:34 PM org.eclipse.californium.core.network.Matcher sendRequest <-----observe request
FINE: Stored open request by KeyMID[6786 for null:0], KeyToken[a0fcca]
Dec 22, 2015 3:14:34 PM org.eclipse.californium.elements.UDPConnector$Sender work
FINER: UDPConnector (/192.168.13.33:5683) sends 16 bytes to /192.168.13.31:35,195
Dec 22, 2015 3:14:35 PM org.eclipse.californium.elements.UDPConnector$Receiver work <----observe response (1st block)
FINER: UDPConnector (/192.168.13.33:5683) received 1,036 bytes from /192.168.13.31:35,195
Dec 22, 2015 3:14:35 PM org.eclipse.californium.elements.UDPConnector$Receiver work
FINER: UDPConnector (/192.168.13.33:5683) received 7 bytes from /192.168.13.31:35,195
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.Matcher receiveEmptyMessage
FINE: Exchange got reply: Cleaning up KeyMID[6786 for null:0]
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.stack.ReliabilityLayer receiveEmptyMessage
FINER: Cancel retransmission
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.Matcher receiveResponse
FINE: Closed open request with KeyMID[6786 for null:0]
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.stack.ReliabilityLayer receiveResponse
FINEST: Cancel any retransmission
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.stack.ReliabilityLayer receiveResponse
FINER: Response is confirmable, send ACK
Dec 22, 2015 3:14:35 PM org.eclipse.californium.elements.UDPConnector$Sender work
FINER: UDPConnector (/192.168.13.33:5683) sends 4 bytes to /192.168.13.31:35,195
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.stack.BlockwiseLayer findResponseBlockStatus
FINER: There is no blockwise status yet. Create and set new Block2 status: [currentNum=0, currentSzx=5, complete=false, random access=false]
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.stack.BlockwiseLayer receiveResponse
FINER: Requesting next Block2 num=1
<block2 exchange in progress>
FINE: Exchange got reply: Cleaning up KeyMID[6804 for null:0] <-----penultimate block
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.stack.ReliabilityLayer receiveEmptyMessage
FINER: Cancel retransmission
Dec 22, 2015 3:14:35 PM org.eclipse.californium.elements.UDPConnector$Receiver work
FINER: UDPConnector (/192.168.13.33:5683) received 768 bytes from /192.168.13.31:35,195
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.Matcher receiveResponse
FINE: Closed open request with KeyMID[6804 for null:0]
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.stack.ReliabilityLayer receiveResponse
FINEST: Cancel any retransmission
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.stack.ReliabilityLayer receiveResponse
FINER: Response is confirmable, send ACK
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.stack.BlockwiseLayer findResponseBlockStatus
FINER: Current Block2 status: [currentNum=18, currentSzx=5, complete=false, random access=false]
Dec 22, 2015 3:14:35 PM org.eclipse.californium.elements.UDPConnector$Sender work
FINER: UDPConnector (/192.168.13.33:5683) sends 4 bytes to /192.168.13.31:35,195
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.stack.BlockwiseLayer receiveResponse
FINER: We have received all 19 blocks of the response. Assemble and deliver
Dec 22, 2015 3:14:35 PM org.eclipse.californium.core.network.stack.BlockwiseLayer receiveResponse
FINE: Assembled response: CON-2.05 MID= 19, Token=a0fcca, OptionSet={"Observe":0, "Block2":"(szx=6/1024, m=false, num=18)"}, <-----server has answered observe request with block2 option OK
c4 03 00 00 00 10 c8 04 0c 34 2e 36 2e 30 2e 72 65 67 2d 31 30 c8 05 1f 31 41 32 31 30 31 30 36
30 30 30 37 30 30 30 30 30 30 30 30 30 30 30 30 30 30 30 30 30 30 30 c5 06 33 2e 30 2e 32 c4 07
52 56 35 30 c8 08 3e 53 57 49 39 58 31 35 43 5f 30 35 2e 30 35 2e 35 38 2e 30 30 20 72 32 37 30
33 38 20 63 61 72 6d 64 2d 66 77 62 75 69 6c 64 31 20 32 30 31 35 2f 30 33 2f 30 34 20 32 31 3a
33 30 3a 32 33 c6 09 4d 43 37 33 30 34 c8 0a 0f 33 35 36 38 35 33 30 35 31 33 33 39 33 32 35 c2
11 4e 41 c8 19 10 4c 54 35 33 35 33 30 30 34 31 30 32 31 30 32 35 c3 1b 4c 54 45 c8 42 11 30 30
3a 31 34 3a 33 65 3a 31 38 3a 62 61 3a 61 34 c8 45 11 30 30 3a 31 34 3a 33 45 3a 31 38 3a 42 41
3a 41 35 e8 01 03 0d 4e 65 74 77 6f 72 6b 20 52 65 61 64 79 e4 01 04 00 00 29 d8 e4 01 05 ff ff
.. 19188 bytes
<many CON notify OK 1 every 2 seconds>
FINER: UDPConnector (/192.168.13.33:5683) received 16 bytes from /192.168.13.31:35,195 <-----CON notify OK
Dec 22, 2015 3:24:34 PM org.eclipse.californium.core.network.Matcher receiveResponse
FINE: Closed open request with KeyMID[6804 for null:0] <-----strange this one keeps repeating (penultimate block)
Dec 22, 2015 3:24:34 PM org.eclipse.californium.core.network.stack.ReliabilityLayer receiveResponse
FINEST: Cancel any retransmission
Dec 22, 2015 3:24:34 PM org.eclipse.californium.core.network.stack.ReliabilityLayer receiveResponse
FINER: Response is confirmable, send ACK
Dec 22, 2015 3:24:34 PM org.eclipse.californium.elements.UDPConnector$Sender work
FINER: UDPConnector (/192.168.13.33:5683) sends 4 bytes to /192.168.13.31:35,195
Dec 22, 2015 3:24:35 PM org.eclipse.californium.core.network.stack.BlockwiseLayer$BlockCleanupTask run <-----cleanup task
INFO: Block2 transfer timed out: CON-GET MID= 6786, Token=a0fcca, OptionSet={"Observe":0, "Uri-Path":["10250","0"]}, no payload
Dec 22, 2015 3:24:36 PM org.eclipse.californium.elements.UDPConnector$Receiver work
FINER: UDPConnector (/192.168.13.33:5683) received 16 bytes from /192.168.13.31:35,195 <-----CON notify KO
Dec 22, 2015 3:24:36 PM org.eclipse.californium.core.network.CoapEndpoint$InboxImpl receiveMessage
FINE: Rejecting unmatchable response from /192.168.13.31:35195 <-----rejected (and interpreted as an observe cancel server side)
Dec 22, 2015 3:24:36 PM org.eclipse.californium.elements.UDPConnector$Sender work
FINER: UDPConnector (/192.168.13.33:5683) sends 4 bytes to /192.168.13.31:35,195
{log from californium}
Gilles Cannenterre
Main: +33 (0)5 61 00 52 90
Fax: +33 (0)5 61 00 51 46
gcannenterre@xxxxxxxxxxxxxxxxxx Lake Park
ZAC de l\'Hers - Allée du Lac
BP 87216
31672 Labège Cedex - France
www.anyware-tech.com
This message and any attachments (the "Message") are confidential and intended solely for the addressees. Any unauthorized modification, edition, use or dissemination is prohibited. Neither Sierra Wireless nor any of its subsidiaries shall be liable for the Message if altered, changed, falsified or edited, diffused without authorization.
________________________________________
De : cf-dev-bounces@xxxxxxxxxxx [cf-dev-bounces@xxxxxxxxxxx] de la part de Kovatsch Matthias [kovatsch@xxxxxxxxxxx]
Date d'envoi : vendredi 18 décembre 2015 14:07
À : Californium (Cf) developer discussions
Objet : Re: [cf-dev] RE : Clean-up mechanism for blockwise transfer is removing observe state
Hi all
Californium handles the blockwise transfer of large notifications in a separate exchange (as it should be done). If the client does not get the blocks in time, only this separate exchange is cleaned up.
I have been running some tests with Copper and observe keeps working over a long time, with and without getting the remaining blocks.
>From the logs, it is hard to see why the LWM2M Server rejects the notifications (probably because the relation was dropped, but why?).
I could not find the details about the proxy issue. However, make sure you dimension the cleanup timeout according to the speed of your client. Also make sure that all blocks of a large notification can be collected between notifications; a minimum period (pmin) might be necessary, if notifications are too big.
Ciao
Matthias
From: cf-dev-bounces@xxxxxxxxxxx [mailto:cf-dev-bounces@xxxxxxxxxxx] On Behalf Of rahxepon12 .
Sent: Freitag, 18. Dezember 2015 11:32
To: Californium (Cf) developer discussions <cf-dev@xxxxxxxxxxx>
Subject: Re: [cf-dev] RE : Clean-up mechanism for blockwise transfer is removing observe state
Hi,
I have posted about the same issue while using the proxy example in a project. So this not only related to observe.
Jo
On Thu, Dec 17, 2015 at 11:33 AM, Gilles Cannenterre <gcannenterre@xxxxxxxxxxxxxxxxxx<mailto:gcannenterre@xxxxxxxxxxxxxxxxxx>> wrote:
Hi Julien,
Yes we are. The observe is OK, notifications are well received and displayed but at some point the server start rejecting notifications.
{capture from leshan UI}
11:17:20.321 NON-2.05 437 4a6e97e1 Observe: Hex:e4280a00000000
11:17:20.377 NON-2.05 439 4a6e97e1 Observe: Hex:e4280a00000001
11:17:25.432 NON-2.05 441 4a6e97e1 Observe: Hex:e4280a00000000
11:17:25.487 NON-2.05 443 4a6e97e1 Observe: Hex:e4280a00000001
11:17:30.551 NON-2.05 445 4a6e97e1 Observe: Hex:e4280a00000000
11:17:30.551 RST- 445
11:17:30.596 NON-2.05 447 4a6e97e1 Observe: Hex:e4280a00000001
11:17:30.596 RST- 447
11:17:35.662 NON-2.05 449 4a6e97e1 Observe: Hex:e4280a00000000
11:17:35.663 RST- 449
{capture from leshan UI}
Gilles Cannenterre
Main: +33 (0)5 61 00 52 90
Fax: +33 (0)5 61 00 51 46
gcannenterre@xxxxxxxxxxxxxxxxxx<mailto:gcannenterre@xxxxxxxxxxxxxxxxxx> Lake Park
ZAC de l\'Hers - Allée du Lac
BP 87216
31672 Labège Cedex - France
www.anyware-tech.com<http://www.anyware-tech.com>
This message and any attachments (the "Message") are confidential and intended solely for the addressees. Any unauthorized modification, edition, use or dissemination is prohibited. Neither Sierra Wireless nor any of its subsidiaries shall be liable for the Message if altered, changed, falsified or edited, diffused without authorization.
________________________________________
De : cf-dev-bounces@xxxxxxxxxxx<mailto:cf-dev-bounces@xxxxxxxxxxx> [cf-dev-bounces@xxxxxxxxxxx<mailto:cf-dev-bounces@xxxxxxxxxxx>] de la part de Julien Vermillard [jvermillard@xxxxxxxxx<mailto:jvermillard@xxxxxxxxx>]
Date d'envoi : jeudi 17 décembre 2015 10:44
À : Californium (Cf) developer discussions
Objet : Re: [cf-dev] Clean-up mechanism for blockwise transfer is removing observe state
Hi,
Do you use different message Ids for the different notification messages?
--
Julien Vermillard
On Wed, Dec 16, 2015 at 6:11 PM, Gilles Cannenterre <gcannenterre@xxxxxxxxxxxxxxxxxx<mailto:gcannenterre@xxxxxxxxxxxxxxxxxx><mailto:gcannenterre@xxxxxxxxxxxxxxxxxx<mailto:gcannenterre@xxxxxxxxxxxxxxxxxx>>> wrote:
Hi all,
I have been using observe on a big object requiring Block2 option on the initial observe request.
This is handled nicely on leshan sandbox server but after sometimes (a few minutes) the notification associated to the said object are rejected with CoAP reset messages.
I have switched back to a local leshan instance and noted that prior to the notification being rejected I have this message in the server console:
Dec 16, 2015 5:13:01 PM org.eclipse.californium.core.network.stack.BlockwiseLayer$BlockCleanupTask run
INFO: Block2 transfer timed out: CON-GET MID= 2565, Token=e0d964cec5, OptionSet={"Observe":0, "Uri-Path":["<my object id here>","0"]}, no payload
It seems like the blockwise transfer cleaning task is cleaning to much...
Gilles
_______________________________________________
cf-dev mailing list
cf-dev@xxxxxxxxxxx<mailto:cf-dev@xxxxxxxxxxx><mailto:cf-dev@xxxxxxxxxxx<mailto: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<mailto: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
