search

eclipse-leshan / leshan

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

send_request causes nullpointer exception #507

Closed lindemanni13 closed 6 years ago

lindemanni13 commented 6 years ago

Hello, I have issue with calling server.send function ass instructed in getting started guide: https://github.com/eclipse/leshan/wiki/Getting-Started-:-Server

I have a client device using mbed-client and nb-iot modem to connect to server. with demo-server registration and read read request works correctly. However with my code, registration works but sending read request causes null pointer exception. I also noticed that the coap request is cancelled and doesn't leave the server All help is very much appreciated

here is the debug log from server:

17:01:09.667 [main] DEBUG org.eclipse.leshan.core.model.DDFFileParser - Parsing DDF file /models/LWM2M_Software_Management-v1_0.xml 17:01:09.669 [main] DEBUG org.eclipse.leshan.core.model.DDFFileParser - Parsing DDF file /models/Non-Access_Stratum_NAS_configuration-V1_0.xml 17:01:09.697 [main] INFO org.eclipse.californium.core.network.config.NetworkConfig - loading properties from file /home/tuolin/testmaven/Californium.properties 17:01:09.747 [main] INFO org.eclipse.californium.core.network.RandomTokenGenerator - using tokens of 8 bytes in length 17:01:09.774 [main] INFO org.eclipse.californium.core.network.CoapEndpoint - CoapEndpoint uses udp plain 17:01:09.798 [main] INFO org.eclipse.californium.core.network.stack.BlockwiseLayer - BlockwiseLayer uses MAX_MESSAGE_SIZE=1024, PREFERRED_BLOCK_SIZE=512, BLOCKWISE_STATUS_LIFETIME=300000 and MAX_RESOURCE_BODY_SIZE=8192 17:01:09.799 [main] INFO org.eclipse.californium.core.network.stack.ReliabilityLayer - ReliabilityLayer uses ACK_TIMEOUT=2000, ACK_RANDOM_FACTOR=1.5, and ACK_TIMEOUT_SCALE=2.0 17:01:09.842 [main] INFO org.eclipse.californium.scandium.dtls.InMemoryConnectionStore - Created new InMemoryConnectionStore [capacity: 150000, connection expiration threshold: 600s] 17:01:09.843 [main] INFO org.eclipse.californium.core.network.RandomTokenGenerator - using tokens of 8 bytes in length 17:01:09.843 [main] INFO org.eclipse.californium.core.network.CoapEndpoint - CoapEndpoint uses lwm2m correlation 17:01:09.843 [main] INFO org.eclipse.californium.core.network.stack.BlockwiseLayer - BlockwiseLayer uses MAX_MESSAGE_SIZE=1024, PREFERRED_BLOCK_SIZE=512, BLOCKWISE_STATUS_LIFETIME=300000 and MAX_RESOURCE_BODY_SIZE=8192 17:01:09.843 [main] INFO org.eclipse.californium.core.network.stack.ReliabilityLayer - ReliabilityLayer uses ACK_TIMEOUT=2000, ACK_RANDOM_FACTOR=1.5, and ACK_TIMEOUT_SCALE=2.0 17:01:09.896 [main] INFO org.eclipse.californium.core.CoapServer - Starting server 17:01:09.897 [main] DEBUG org.eclipse.californium.core.network.CoapEndpoint - Starting endpoint at coap://0.0.0.0:5683 17:01:09.918 [main] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - no MessageIdProvider set, using default org.eclipse.californium.core.network.InMemoryMessageIdProvider 17:01:09.924 [main] INFO org.eclipse.californium.elements.UDPConnector - UDPConnector starts up 1 sender threads and 1 receiver threads 17:01:09.930 [main] INFO org.eclipse.californium.elements.UDPConnector - UDPConnector listening on 0.0.0.0/0.0.0.0:5683, recv buf = 106496, send buf = 106496, recv packet size = 2048 17:01:09.932 [main] INFO org.eclipse.californium.core.network.CoapEndpoint - Started endpoint at coap://0.0.0.0:5683 17:01:09.932 [main] DEBUG org.eclipse.californium.core.network.CoapEndpoint - Starting endpoint at coaps://0.0.0.0:5684 17:01:09.933 [main] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - no MessageIdProvider set, using default org.eclipse.californium.core.network.InMemoryMessageIdProvider 17:01:09.935 [main] INFO org.eclipse.californium.scandium.DTLSConnector - Cannot determine MTU of network interface, using minimum MTU [1280] of IPv6 instead 17:01:09.937 [main] INFO org.eclipse.californium.scandium.DTLSConnector - DTLS connector listening on [0.0.0.0/0.0.0.0:5684] with MTU [1280] using (inbound) datagram buffer size [16474 bytes] 17:01:09.937 [main] INFO org.eclipse.californium.core.network.CoapEndpoint - Started endpoint at coaps://0.0.0.0:5684 17:01:09.937 [main] INFO org.eclipse.leshan.server.californium.impl.LeshanServer - LWM2M server started at coap://0.0.0.0/0.0.0.0:5683 coaps://0.0.0.0/0.0.0.0:5684 17:01:09.929 [UDP-Receiver-0.0.0.0/0.0.0.0:5683[0]] DEBUG org.eclipse.californium.elements.UDPConnector - Starting network stage thread [UDP-Receiver-0.0.0.0/0.0.0.0:5683[0]] 17:01:09.931 [UDP-Sender-0.0.0.0/0.0.0.0:5683[0]] DEBUG org.eclipse.californium.elements.UDPConnector - Starting network stage thread [UDP-Sender-0.0.0.0/0.0.0.0:5683[0]] 17:01:09.939 [DTLS-Receiver-0.0.0.0/0.0.0.0:5684] INFO org.eclipse.californium.scandium.DTLSConnector - Starting worker thread [DTLS-Receiver-0.0.0.0/0.0.0.0:5684] 17:01:23.405 [UDP-Receiver-0.0.0.0/0.0.0.0:5683[0]] DEBUG org.eclipse.californium.elements.UDPConnector - UDPConnector (0.0.0.0/0.0.0.0:5683) received 212 bytes from /83.100.36.28:49152 17:01:23.426 [CoapServer#1] DEBUG org.eclipse.leshan.server.californium.impl.RegisterResource - POST received : CON-POST MID=16477, Token=[], OptionSet={"Uri-Path":"rd", "Uri-Query":["ep=Quectel_endpoint_test","et=test","lt=100","b=UQ"]}, "</3200/0/5502>;rt="Timer".. 158 bytes 17:01:23.445 [CoapServer#1] DEBUG org.eclipse.leshan.server.registration.RegistrationHandler - New registration: Registration [registrationDate=Thu May 24 17:01:23 EEST 2018, identity=Identity /83.100.36.28:49152[unsecure], registrationEndpoint=0.0.0.0/0.0.0.0:5683, lifeTimeInSec=100, smsNumber=null, lwM2mVersion=1.0, bindingMode=UQ, endpoint=Quectel_endpoint_test, registrationId=3zBY7Q3eJw, objectLinks=[</3200/0/5502>;obs;rt="Timer", </1000/0/1>;obs;rt="BigData", </3201/0/5850>;rt="Blink", </3201/0/5853>;rt="Pattern", </3200/0/5501>;obs;rt="Button", </3/0>;ct="99"], lastUpdate=Thu May 24 17:01:23 EEST 2018] 17:01:23.484 [CoapServer#1] DEBUG org.eclipse.californium.core.network.stack.ReliabilityLayer - Send response, failed transmissions: 0 client woke up: Quectel_endpoint_test new device: Quectel_endpoint_test 17:01:23.497 [UDP-Sender-0.0.0.0/0.0.0.0:5683[0]] DEBUG org.eclipse.californium.elements.UDPConnector - UDPConnector (Thread[UDP-Sender-0.0.0.0/0.0.0.0:5683[0],5,Californium/Elements]) sent 18 bytes to /83.100.36.28:49152 17:01:29.911 [Deduplicator1] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms 17:01:33.499 [CoapServer#1] DEBUG org.eclipse.leshan.core.californium.SyncRequestObserver - Synchronous request cancelled CON-GET MID= -1, Token=null, OptionSet={"Uri-Path":["3200","0","5501"]}, no payload client went to sleep: Quectel_endpoint_test 17:01:33.515 [CoapServer#1] ERROR org.eclipse.leshan.server.impl.SendableResponse - Exception while calling the reponse sent callback java.lang.NullPointerException: null at lwm2mtest.lwm2mServer$3.send_request(lwm2mServer.java:205) at lwm2mtest.lwm2mServer$3.registered(lwm2mServer.java:218) at org.eclipse.leshan.server.impl.RegistrationServiceImpl.fireRegistered(RegistrationServiceImpl.java:80) at org.eclipse.leshan.server.registration.RegistrationHandler$1.run(RegistrationHandler.java:84) at org.eclipse.leshan.server.impl.SendableResponse.sent(SendableResponse.java:48) at org.eclipse.leshan.server.californium.impl.RegisterResource.handleRegister(RegisterResource.java:200) at org.eclipse.leshan.server.californium.impl.RegisterResource.handlePOST(RegisterResource.java:117) at org.eclipse.californium.core.CoapResource.handleRequest(CoapResource.java:217) at org.eclipse.leshan.server.californium.impl.RegisterResource.handleRequest(RegisterResource.java:85) at org.eclipse.californium.core.server.ServerMessageDeliverer.deliverRequest(ServerMessageDeliverer.java:106) at org.eclipse.californium.core.network.stack.BaseCoapStack$StackTopAdapter.receiveRequest(BaseCoapStack.java:164) at org.eclipse.californium.core.network.stack.AbstractLayer.receiveRequest(AbstractLayer.java:81) at org.eclipse.californium.core.network.stack.AbstractLayer.receiveRequest(AbstractLayer.java:81) at org.eclipse.californium.core.network.stack.BlockwiseLayer.receiveRequest(BlockwiseLayer.java:330) at org.eclipse.californium.core.network.stack.ReliabilityLayer.receiveRequest(ReliabilityLayer.java:248) at org.eclipse.californium.core.network.stack.AbstractLayer.receiveRequest(AbstractLayer.java:81) at org.eclipse.californium.core.network.stack.BaseCoapStack.receiveRequest(BaseCoapStack.java:99) at org.eclipse.californium.core.network.CoapEndpoint$InboxImpl.receiveRequest(CoapEndpoint.java:869) at org.eclipse.californium.core.network.CoapEndpoint$InboxImpl.receiveMessage(CoapEndpoint.java:802) at org.eclipse.californium.core.network.CoapEndpoint$InboxImpl.access$1000(CoapEndpoint.java:765) at org.eclipse.californium.core.network.CoapEndpoint$InboxImpl$1.run(CoapEndpoint.java:781) at org.eclipse.californium.core.network.CoapEndpoint$5.run(CoapEndpoint.java:1013) at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:514) 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:1135) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:844) 17:01:33.517 [CoapServer#1] DEBUG org.eclipse.californium.core.network.stack.ReliabilityLayer - Send request, failed transmissions: 0 17:01:33.518 [CoapServer#1] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - exchange added with generated mid KeyMID[37972, [5364241c]:49152], CON-GET MID=37972, Token=null, OptionSet={"Uri-Path":["3200","0","5501"]}, no payload 17:01:33.523 [CoapServer#1] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - exchange added with generated token Token=[9261cc4a74d0a4eb], CON-GET MID=37972, Token=[9261cc4a74d0a4eb], OptionSet={"Uri-Path":["3200","0","5501"]}, no payload 17:01:33.525 [CoapServer#1] DEBUG org.eclipse.californium.core.network.UdpMatcher - tracking open request [MID: 37972, Token: [9261cc4a74d0a4eb]] 17:01:33.525 [CoapServer#1] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - removing exchange for MID KeyMID[37972, [5364241c]:49152] 17:01:33.525 [CoapServer#1] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - removing exchange for token Token=[9261cc4a74d0a4eb] 17:01:33.526 [CoapServer#1] DEBUG org.eclipse.californium.core.network.UdpMatcher - Exchange [Token=[9261cc4a74d0a4eb], origin: LOCAL] completed

here is the meaningful part of code:

lwServer.getRegistrationService().addListener(new RegistrationListener() { private void sleep(int time){ try { Thread.sleep(time); } catch(InterruptedException ex) { Thread.currentThread().interrupt(); } } private void send_request(Registration registration){ try { long timeout = 10000; ContentFormat contentFormat = ContentFormat.fromName("TEXT_PLAIN"); String target = "/3200/0/5501"; ReadRequest request = new ReadRequest(contentFormat, target); ReadResponse response = lwServer.send(registration, request, timeout); if (response.isSuccess()) { System.out.println("Device timer:" + ((LwM2mResource)response.getContent()).getValue()); }else { System.out.println("Failed to read:" + response.getCode() + " " + response.getErrorMessage()); } } catch ( InterruptedException e) { System.out.println("* exeption occured !!! *****"); e.printStackTrace(); } } public void registered(Registration registration, Registration previousReg, Collection previousObsersations) { System.out.println("new device: " + registration.getEndpoint()); send_request(registration); //sleep(1000); //send_request(registration); }

            public void updated(RegistrationUpdate update, Registration updatedReg, Registration previousReg) {
                    System.out.println("device is still here: " + updatedReg.getEndpoint());
                    //sleep(500);
                    //send_request(updatedReg);
            }

            public void unregistered(Registration registration, Collection<Observation> observations, boolean expired,
                    Registration newReg) {
                    System.out.println("device left: " + registration.getEndpoint());
            }
    } //new registrationlistener
    );//addlistener

and here is the pom.xml:

<?xml version="1.0" encoding="UTF-8"?> <project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/maven-v4_0_0.xsd">

4.0.0 
<groupId>org.springframework</groupId>
<artifactId>gs-maven</artifactId>
<packaging>jar</packaging>
<version>0.2.0</version>

<properties>
    <maven.compiler.source>1.8</maven.compiler.source>
    <maven.compiler.target>1.8</maven.compiler.target>
</properties>
org.jmdns jmdns 3.5.2 org.eclipse.leshan leshan-server-cluster 1.0.0-SNAPSHOT commons-cli commons-cli 1.3.1 org.eclipse.californium californium-core 2.0.0-M9 commons-io commons-io 2.4 commons-lang commons-lang 2.6 org.eclipse.jetty jetty-webapp 9.1.4.v20140401 org.eclipse.jetty jetty-continuation 9.1.4.v20140401 com.google.code.gson gson 2.2.4 ch.qos.logback logback-classic 1.2.3 runtime org.eclipse.leshan leshan-server-cf 1.0.0-M6 org.slf4j slf4j-simple 1.7.10 runtime 
<build>
    <plugins>
        <plugin>
            <groupId>org.apache.maven.plugins</groupId>
            <artifactId>maven-shade-plugin</artifactId>
            <version>2.1</version>
            <executions>
                <execution>
                    <phase>package</phase>
                    <goals>
                        <goal>shade</goal>
                    </goals>
                    <configuration>
                        <filters>
                            <filter>
                               <artifact>*:*</artifact>
                               <excludes>
                                  <exclude>META-INF/*.SF</exclude>
                                  <exclude>META-INF/*.DSA</exclude>
                                  <exclude>META-INF/*.RSA</exclude>
                               </excludes>
                            </filter>

´

lwm2mtest.lwm2mServer 
                    </configuration>
                </execution>
            </executions>
        </plugin>
    </plugins>
</build>

sbernard31 commented 6 years ago

I see at leat an error here :

ContentFormat.fromName("TEXT_PLAIN");

This is TEXT not TEXT_PLAIN, see : https://github.com/eclipse/leshan/blob/master/leshan-core/src/main/java/org/eclipse/leshan/core/request/ContentFormat.java#L34

lindemanni13 commented 6 years ago

Thanks for identifying that ( ContentFormat.fromName("TEXT_PLAIN"); ), but it doesn't seem to be the main issue, as I still get the same exception after fixing it... I think the the main issue is that coap request is cancelled:

17:01:33.499 [CoapServer#1] DEBUG org.eclipse.leshan.core.californium.SyncRequestObserver - Synchronous request cancelled CON-GET MID= -1, Token=null, OptionSet={"Uri-Path":["3200","0","5501"]}, no payload

,but i don't know what causes it and therefore how to fix... also it seems that MID is set after the cancellation:

17:01:33.518 [CoapServer#1] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - exchange added with generated mid KeyMID[37972, [5364241c]:49152], CON-GET MID=37972, Token=null, OptionSet={"Uri-Path":["3200","0","5501"]}, no payload

sbernard31 commented 6 years ago

the stacktrace say : 

java.lang.NullPointerException: null
at lwm2mtest.lwm2mServer$3.send_request(lwm2mServer.java:205)
at lwm2mtest.lwm2mServer$3.registered(lwm2mServer.java:218)
at org.eclipse.leshan.server.impl.RegistrationServiceImpl.fireRegistered(RegistrationServiceImpl.java:80)
at org.eclipse.leshan.server.registration.RegistrationHandler$1.run(RegistrationHandler.java:84)
at org.eclipse.leshan.server.impl.SendableResponse.sent(SendableResponse.java:48)

what is exactly the line 205 of the lwm2mtest.lwm2mServer file ?

lindemanni13 commented 6 years ago

the line 205 is:

if (response.isSuccess()) {

in previous line: ReadResponse response = lwServer.send(registration, request, timeout);

method: send returns null...

sbernard31 commented 6 years ago

So if you read the javadoc, 

@return the response or <code>null</code> if the CoAP timeout expires

So this means that you device does not answer in time. The question is why ?

Do you face the same issue without DTLS ? Did you try to do a wireshark capture to see what happened at network layer ? Do you have any log from device ?

lindemanni13 commented 6 years ago

2018-05-28 15:17:43,081 DEBUG InMemoryMessageExchangeStore - exchange added with generated mid KeyMID[1467, [536471f0]:49153], CON-GET MID= 1467, Token=null, OptionSet={"Uri-Path":["3200","0","5502"], "Accept":"application/vnd.oma.lwm2m+tlv"}, no payload 2018-05-28 15:17:43,083 DEBUG InMemoryMessageExchangeStore - exchange added with generated token Token=[70421a6356bc00dd], CON-GET MID= 1467, Token=[70421a6356bc00dd], OptionSet={"Uri-Path":["3200","0","5502"], "Accept":"application/vnd.oma.lwm2m+tlv"}, no payload 2018-05-28 15:17:43,084 DEBUG UdpMatcher - tracking open request [MID: 1467, Token: [70421a6356bc00dd]] 2018-05-28 15:17:43,085 DEBUG EventServlet - Dispatching COAPLOG event from endpoint Quectel_endpoint_test 2018-05-28 15:17:43,085 DEBUG UDPConnector$Sender - UDPConnector (Thread[UDP-Sender-0.0.0.0/0.0.0.0:5683[0],5,Californium/Elements]) sent 27 bytes to /83.100.113.240:49153 2018-05-28 15:17:44,107 DEBUG UDPConnector$Receiver - UDPConnector (0.0.0.0/0.0.0.0:5683) received 16 bytes from /83.100.113.240:49153

and all works fine...

... and the message does not leave server as in leshan-demo-server, so what causes the message to be cancelled?

lindemanni13 commented 6 years ago
sbernard31 commented 6 years ago 
17:01:23.497 [UDP-Sender-0.0.0.0/0.0.0.0:5683[0]] DEBUG org.eclipse.californium.elements.UDPConnector - UDPConnector (Thread[UDP-Sender-0.0.0.0/0.0.0.0:5683[0],5,Californium/Elements]) sent 18 bytes to /83.100.36.28:49152
17:01:33.499 [CoapServer#1] DEBUG org.eclipse.leshan.core.californium.SyncRequestObserver - Synchronous request cancelled CON-GET MID= -1, Token=null, OptionSet={"Uri-Path":["3200","0","5501"]}, no payload

The request is cancelled 10s later it was sent because you set a timeout of 10s. This makes sense to me, but I do not understand why this message is never sent ? I understand well, you don't see the read request (coap get) in your tcpdump capture ?

lindemanni13 commented 6 years ago

yes, there is no read request(coap get) been sent by server, accordin to tcpdump

sbernard31 commented 6 years ago

Ok I maybe get it. I suspect that you are running your example on a machine which as only one core ? is it right ?

To check if this is the problem, you can : 1) use the async send API instead of the sync API (send method with ResponseCallback) or 2) increase manually the number of thread of CoAP protocol stage builder.setCoapConfig(LeshanClientBuilder.createDefaultNetworkConfig().set(NetworkConfig.Keys.PROTOCOL_STAGE_THREAD_COUNT, 4));

lindemanni13 commented 6 years ago

Yes you are right, I have only one core... Thanks a lot, I would never figured that out on my own. I will inform if I get it working now.

lindemanni13 commented 6 years ago

That fixed the issue! I used LeshanServerBuilder instead of LeshanClientBuilder, but nevertheles works fine! Thank you very much once again!

PiotrFaj commented 5 years ago

Hello, Colleagues, thank you for solving my problem, big beer. Thank you very much !!!