search

eclipse-leshan / leshan

Java Library for LWM2M
https://www.eclipse.org/leshan/
BSD 3-Clause "New" or "Revised" License
652 stars 407 forks source link

Leshan does not decode SenML-CBOR/JSON data value (vd/8) correctly #984

Closed jacintobarbeira closed 3 years ago

jacintobarbeira commented 3 years ago

Hi Leshan Team

I'm trying out the AVSystem's Coiote LwM2M stack (both bootstrap and device management) using Leshan client demo. When I connect the client to the bootstrap server, I get this error when the server sends back the device manager info to connect to:

2021-03-19 14:26:48,006 ERROR LwM2mCoapResource - Exception while handling request [CON-PUT    MID= 7581, Token=3EA719C0258E200B, OptionSet={"Uri-Path":"0", "Content-Format":"application/senml+cbor"},
8d a3 21 63 2f 30 2f 00 63 31 2f 30 03 78 23 63 6f 61 70 73 3a 2f 2f 6c 77 6d 32 6d 2d 74 65 73
74 2e 61 76 73 79 73 74 65 6d 2e 69 6f 3a 35 36 39 34 a2 00 63 31 2f 32 02 00 a2 00 63 31 2f 33
08 47 74 65 73 74 2d 6a 62 a2 00 63 31 2f 35 08 58 18 58 59 37 6d 73 43 46 4f 30 47 61 67 64 34
46 77 6b 56 36 6f 36 6a 6b 33 a2 00 63 31 2f 34 08 40 a2 00 63 31 2f 31 04 f5 a2 00 63 32 2f 30
03 78 23 63 6f 61 70 73 3a 2f 2f 6c 77 6d 32 6d 2d 74 65 73 74 2e 61 76 73 79 73 74 65 6d 2e 69
6f 3a 35 36 38 34 a2 00 63 32 2f 32 02 00 a2 00 63 32 2f 33 08 47 74 65 73 74 2d 6a 62 a2 00 63
32 2f 35 08 58 18 6b 72 56 63 43 62 6e 55 61 42 56 72 53 35 48 59 32 52 42 51 4e 72 52 76 a2 00
63 32 2f 34 08 40 a2 00 63 32 2f 31 04 f4 a2 00 64 32 2f 31 30 02 01 ] on the resource /0 from Identity lwm2m-test.avsystem.io/35.241.179.127:5694[psk=test-jb]
org.eclipse.leshan.core.util.json.JsonException: Invalid SenML record : record must have a value (v,vb,vlo,vd,vs) : {0: "1/3", 8: h'746573742D6A62'}
    at org.eclipse.leshan.senml.cbor.upokecenter.SenMLCborPackSerDes.deserializeFromCbor(SenMLCborPackSerDes.java:117)
    at org.eclipse.leshan.senml.cbor.upokecenter.SenMLCborUpokecenterEncoderDecoder.fromSenML(SenMLCborUpokecenterEncoderDecoder.java:72)
    at org.eclipse.leshan.core.node.codec.senml.LwM2mNodeSenMLDecoder.decode(LwM2mNodeSenMLDecoder.java:68)
    at org.eclipse.leshan.core.node.codec.DefaultLwM2mNodeDecoder.decode(DefaultLwM2mNodeDecoder.java:127)
    at org.eclipse.leshan.core.node.codec.DefaultLwM2mNodeDecoder.decode(DefaultLwM2mNodeDecoder.java:109)
    at org.eclipse.leshan.client.californium.object.ObjectResource.handlePUT(ObjectResource.java:228)
    at org.eclipse.californium.core.CoapResource.handleRequest(CoapResource.java:228)
    at org.eclipse.leshan.core.californium.LwM2mCoapResource.handleRequest(LwM2mCoapResource.java:51)
    at org.eclipse.californium.core.server.ServerMessageDeliverer.deliverRequest(ServerMessageDeliverer.java:106)
    at org.eclipse.californium.core.network.stack.BaseCoapStack$StackTopAdapter.receiveRequest(BaseCoapStack.java:204)
    at org.eclipse.californium.core.network.stack.AbstractLayer.receiveRequest(AbstractLayer.java:84)
    at org.eclipse.californium.core.network.stack.AbstractLayer.receiveRequest(AbstractLayer.java:84)
    at org.eclipse.californium.core.network.stack.BlockwiseLayer.receiveRequest(BlockwiseLayer.java:413)
    at org.eclipse.californium.core.network.stack.ReliabilityLayer.receiveRequest(ReliabilityLayer.java:275)
    at org.eclipse.californium.core.network.stack.AbstractLayer.receiveRequest(AbstractLayer.java:84)
    at org.eclipse.californium.core.network.stack.BaseCoapStack.receiveRequest(BaseCoapStack.java:137)
    at org.eclipse.californium.core.network.CoapEndpoint$1.receiveRequest(CoapEndpoint.java:309)
    at org.eclipse.californium.core.network.UdpMatcher$2.run(UdpMatcher.java:270)
    at org.eclipse.californium.elements.util.SerialExecutor$1.run(SerialExecutor.java:289)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:836)
2021-03-19 14:28:19,770 INFO DefaultRegistrationEngine - Bootstrap sequence aborted: Timeout.

I asked about it and the guys at AV Systems say that it's probably a bug on Leshan's side as it is expecting text labels instead of numeric ones. I've had the same result with master and demo_v2 branches and leshan-2.0.0-M2 tag

BR

Jacinto

sbernard31 commented 3 years ago

Thx a lot to reporting this :pray:

I will investigate this. For now it seems that we expect base64 string for SenML Data Value (vd in json and 8in cbor). This is maybe a bug I need to read SenML and LWM2M specification again.

sbernard31 commented 3 years ago

I confirm this is a bug in Leshan.

LWM2M spec says :

OPAQUE for SenML-CBOR : Represented as a byte string, as defined in Section 2 of [RFC7049]

SenML RFC says :

Octets in the Data Value are encoded using a byte string with a definite length (major type 2).

sbernard31 commented 3 years ago

985 should fix the issue.

Could you confirm it works for you ? :pray:

jacintobarbeira commented 3 years ago

what branch is it on?

jacintobarbeira commented 3 years ago

nevermind just saw it

sbernard31 commented 3 years ago

you can see it in the PR below the title :

sbernard31 wants to merge 1 commit into master from fix_senml_cbor

jacintobarbeira commented 3 years ago

different error this time

2021-03-19 17:05:26,497 DEBUG LwM2mCoapResource - Invalid request [CON-PUT    MID=17397, Token=9532FADA258E200B, OptionSet={"Uri-Path":"0", "Content-Format":"application/senml+cbor"},
8d a3 21 63 2f 30 2f 00 63 31 2f 30 03 78 23 63 6f 61 70 73 3a 2f 2f 6c 77 6d 32 6d 2d 74 65 73
74 2e 61 76 73 79 73 74 65 6d 2e 69 6f 3a 35 36 39 34 a2 00 63 31 2f 32 02 00 a2 00 63 31 2f 33
08 47 74 65 73 74 2d 6a 62 a2 00 63 31 2f 35 08 58 18 51 64 63 4b 37 74 49 4f 4e 4e 78 4a 32 79
55 54 68 30 53 45 76 52 58 4a a2 00 63 31 2f 34 08 40 a2 00 63 31 2f 31 04 f5 a2 00 63 32 2f 30
03 78 23 63 6f 61 70 73 3a 2f 2f 6c 77 6d 32 6d 2d 74 65 73 74 2e 61 76 73 79 73 74 65 6d 2e 69
6f 3a 35 36 38 34 a2 00 63 32 2f 32 02 00 a2 00 63 32 2f 33 08 47 74 65 73 74 2d 6a 62 a2 00 63
32 2f 35 08 58 18 37 47 4c 4f 73 4e 4f 62 74 51 48 63 59 56 4b 46 69 51 52 65 57 34 51 31 a2 00
63 32 2f 34 08 40 a2 00 63 32 2f 31 04 f4 a2 00 64 32 2f 31 30 02 01 ] received on the resource /0 from Identity lwm2m-test.avsystem.io/35.241.179.127:5694[psk=test-jb]
org.eclipse.leshan.core.node.codec.CodecException: Invalid content [[B@dc67221f] for type OPAQUE for path /0/1/3
    at org.eclipse.leshan.core.node.codec.senml.LwM2mNodeSenMLDecoder.parseResourceValue(LwM2mNodeSenMLDecoder.java:496)
    at org.eclipse.leshan.core.node.codec.senml.LwM2mNodeSenMLDecoder.extractLwM2mResources(LwM2mNodeSenMLDecoder.java:416)
    at org.eclipse.leshan.core.node.codec.senml.LwM2mNodeSenMLDecoder.parseRecords(LwM2mNodeSenMLDecoder.java:195)
    at org.eclipse.leshan.core.node.codec.senml.LwM2mNodeSenMLDecoder.decode(LwM2mNodeSenMLDecoder.java:97)
    at org.eclipse.leshan.core.node.codec.DefaultLwM2mNodeDecoder.decode(DefaultLwM2mNodeDecoder.java:155)
    at org.eclipse.leshan.core.node.codec.DefaultLwM2mNodeDecoder.decode(DefaultLwM2mNodeDecoder.java:137)
    at org.eclipse.leshan.client.californium.object.ObjectResource.handlePUT(ObjectResource.java:228)
    at org.eclipse.californium.core.CoapResource.handleRequest(CoapResource.java:228)
    at org.eclipse.leshan.core.californium.LwM2mCoapResource.handleRequest(LwM2mCoapResource.java:51)
    at org.eclipse.californium.core.server.ServerMessageDeliverer.deliverRequest(ServerMessageDeliverer.java:106)
    at org.eclipse.californium.core.network.stack.BaseCoapStack$StackTopAdapter.receiveRequest(BaseCoapStack.java:204)
    at org.eclipse.californium.core.network.stack.AbstractLayer.receiveRequest(AbstractLayer.java:84)
    at org.eclipse.californium.core.network.stack.AbstractLayer.receiveRequest(AbstractLayer.java:84)
    at org.eclipse.californium.core.network.stack.BlockwiseLayer.receiveRequest(BlockwiseLayer.java:413)
    at org.eclipse.californium.core.network.stack.ReliabilityLayer.receiveRequest(ReliabilityLayer.java:275)
    at org.eclipse.californium.core.network.stack.AbstractLayer.receiveRequest(AbstractLayer.java:84)
    at org.eclipse.californium.core.network.stack.BaseCoapStack.receiveRequest(BaseCoapStack.java:137)
    at org.eclipse.californium.core.network.CoapEndpoint$1.receiveRequest(CoapEndpoint.java:309)
    at org.eclipse.californium.core.network.UdpMatcher$2.run(UdpMatcher.java:270)
    at org.eclipse.californium.elements.util.SerialExecutor$1.run(SerialExecutor.java:289)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:836)
Caused by: java.lang.ClassCastException: [B incompatible with java.lang.String
    at org.eclipse.leshan.core.node.codec.senml.LwM2mNodeSenMLDecoder.parseResourceValue(LwM2mNodeSenMLDecoder.java:487)
sbernard31 commented 3 years ago

Thx again I will look at this on Monday hoping I will be able to provide a fix quickly.

jacintobarbeira commented 3 years ago

thks. have a nice weekend :)

sbernard31 commented 3 years ago

I pushed a quick commit on fix_senml_cbor just in case. (not tested at all)

sbernard31 commented 3 years ago

Have a nice weekend too and thx again to report this kind of bug. This helps a lot :pray:

jacintobarbeira commented 3 years ago

failing compilation on integration tests

[ERROR] Failures: 
[ERROR]   QueueModeTest.sleeping_if_timeout:161 expected null, but was:<ReadResponse [code=NOT_FOUND, errormessage=]>
[ERROR]   WriteOpaqueValueTest.write_opaque_resource:92 expected:<CHANGED> but was:<INTERNAL_SERVER_ERROR>
[ERROR]   WriteOpaqueValueTest.write_opaque_resource:92 expected:<CHANGED> but was:<INTERNAL_SERVER_ERROR>
[ERROR] Errors: 
[ERROR]   BootstrapTest.bootstrap_senmlcbor_only:129 » Runtime java.util.concurrent.Time...
[ERROR]   ReadOpaqueValueTest.can_read_empty_opaque_resource:81 » LwM2mNode Value does n...
[ERROR]   ReadOpaqueValueTest.can_read_empty_opaque_resource:81 » LwM2mNode Value does n...
[INFO] 
[ERROR] Tests run: 317, Failures: 3, Errors: 3, Skipped: 0
sbernard31 commented 3 years ago

Ok I finally take time to look at this deeper.

This was not 1 bug but a nest ! nest

I hope this time it's OK.

jacintobarbeira commented 3 years ago

ok, we progressed. The bootstrap task on the server side completes without error, but afterwards the client then throws this:

2021-03-22 16:10:01,098 INFO LeshanClientDemo - Commands available :

  - create <objectId> : to enable a new object.
  - delete <objectId> : to disable a new object.
  - update : to trigger a registration update.
  - w : to move to North.
  - a : to move to East.
  - s : to move to South.
  - d : to move to West.

2021-03-22 16:10:01,098 INFO LeshanClient - Starting Leshan client ...
2021-03-22 16:10:01,103 INFO LeshanClient - Leshan client[endpoint:test-jb] started.
2021-03-22 16:10:01,103 INFO DefaultRegistrationEngine - Trying to start bootstrap session to coaps://lwm2m-test.avsystem.io:5694 ...
2021-03-22 16:10:01,812 INFO CaliforniumEndpointsManager - New endpoint created for server coaps://lwm2m-test.avsystem.io:5694 at coaps://0.0.0.0:64504
2021-03-22 16:10:01,835 INFO LeshanClientDemo - DTLS Full Handshake initiated by client : STARTED ...
2021-03-22 16:10:01,977 INFO LeshanClientDemo - DTLS Full Handshake initiated by client : SUCCEED
2021-03-22 16:10:02,220 INFO DefaultRegistrationEngine - Bootstrap started
2021-03-22 16:10:02,496 DEBUG Security - Write on Security resource /0/1/0
2021-03-22 16:10:02,497 DEBUG Security - Write on Security resource /0/1/1
2021-03-22 16:10:02,497 DEBUG Security - Write on Security resource /0/1/2
2021-03-22 16:10:02,497 DEBUG Security - Write on Security resource /0/1/3
2021-03-22 16:10:02,497 DEBUG Security - Write on Security resource /0/1/4
2021-03-22 16:10:02,497 DEBUG Security - Write on Security resource /0/1/5
2021-03-22 16:10:02,498 DEBUG Security - Write on Security resource /0/2/0
2021-03-22 16:10:02,498 DEBUG Security - Write on Security resource /0/2/1
2021-03-22 16:10:02,498 DEBUG Security - Write on Security resource /0/2/2
2021-03-22 16:10:02,498 DEBUG Security - Write on Security resource /0/2/3
2021-03-22 16:10:02,498 DEBUG Security - Write on Security resource /0/2/4
2021-03-22 16:10:02,498 DEBUG Security - Write on Security resource /0/2/5
2021-03-22 16:10:02,498 DEBUG Security - Write on Security resource /0/2/10
2021-03-22 16:10:02,537 DEBUG Server - Write on Server resource /1/2/0
2021-03-22 16:10:02,537 DEBUG Server - Write on Server resource /1/2/1
2021-03-22 16:10:02,537 DEBUG Server - Write on Server resource /1/2/6
2021-03-22 16:10:02,537 DEBUG Server - Write on Server resource /1/2/7
2021-03-22 16:10:02,612 INFO DefaultRegistrationEngine - Bootstrap finished coaps://lwm2m-test.avsystem.io:5694.
2021-03-22 16:10:02,612 INFO DefaultRegistrationEngine - Unable to send Bootstrap request : null
2021-03-22 16:10:02,613 ERROR DefaultRegistrationEngine - Unexpected exception during bootstrap task
java.lang.NullPointerException
    at org.eclipse.leshan.client.object.Security.read(Security.java:244)
    at org.eclipse.leshan.client.resource.BaseInstanceEnabler.read(BaseInstanceEnabler.java:118)
    at org.eclipse.leshan.client.resource.ObjectEnabler.doRead(ObjectEnabler.java:201)
    at org.eclipse.leshan.client.resource.BaseObjectEnabler.read(BaseObjectEnabler.java:173)
    at org.eclipse.leshan.client.servers.ServersInfoExtractor.getInfo(ServersInfoExtractor.java:69)
    at org.eclipse.leshan.client.servers.ServersInfoExtractor.getBootstrapServerInfo(ServersInfoExtractor.java:150)
    at org.eclipse.leshan.client.engine.DefaultRegistrationEngine.scheduleClientInitiatedBootstrap(DefaultRegistrationEngine.java:493)
    at org.eclipse.leshan.client.engine.DefaultRegistrationEngine.access$500(DefaultRegistrationEngine.java:74)
    at org.eclipse.leshan.client.engine.DefaultRegistrationEngine$ClientInitiatedBootstrapTask.run(DefaultRegistrationEngine.java:524)
    at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
    at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
    at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304)
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
    at java.base/java.lang.Thread.run(Thread.java:836)
2021-03-22 16:10:02,614 INFO LeshanClient - Destroying Leshan client ...
2021-03-22 16:10:02,616 INFO LeshanClient - Leshan client destroyed.
sbernard31 commented 3 years ago

At first sight, I guess this is a another issue not related to CBOR It seems that sever id (/0/?/10) is null after the bootstrap session and leshan client does not like this. I need to investigate more.

sbernard31 commented 3 years ago

I looked at this a little and I'm not sure to understand what happened :/ Could you create a new issue and provide a wireshark capture ?

sbernard31 commented 3 years ago

I created a dedicated issue : #986

jacintobarbeira commented 3 years ago

ok. I'll close this one