eclipse-leshan / leshan

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

Leshan server demo throws null-pointer exception #1580

Closed leandrolanzieri closed 9 months ago

leandrolanzieri commented 9 months ago

Version(s)

leshan-server-demo v2.0.0-SNAPSHOT Commit ID : f23254c85928bf0eba54c10b515b36ef050a6959 Build Date: Wed Jan 31 18:03:33 CET 2024 (1706720613007) JVM: 11.0.21 (Oracle Corporation OpenJDK 64-Bit Server VM 11.0.21+9) OS: Linux 5.10.206-1-MANJARO amd64 Code Source: https://github.com/eclipse/leshan/tree/f23254c85928bf0eba54c10b515b36ef050a6959

Which components

leshan server demo

Tested With

wakaama-based RIOT implementation

What happened

After a successful client registration, attempts to read any resource from the client throw a NullPointerException. No packet is sent to the client.

How to reproduce

Configure and build the lwm2m example using this RIOT PR: https://github.com/RIOT-OS/RIOT/pull/16233

Configure the right credentials on the Leshan server and trigger a registration. Upon successful registration, try to read any resource on the device.

Relevant Output

2024-02-02 14:34:46,768 EventServlet         [DEBUG] Dispatching REGISTRATION event from endpoint testRIOTDevice  
2024-02-02 14:34:47,045 SweepDeduplicator    [TRACE] Start Mark-And-Sweep with 0 entries  
2024-02-02 14:34:47,054 SweepDeduplicator    [TRACE] Start Mark-And-Sweep with 1 entries  
2024-02-02 14:34:47,054 SweepDeduplicator    [DEBUG] Sweep run took 0ms  
2024-02-02 14:34:47,059 DTLSConnector        [TRACE] 1 recent handshakes, cleaning up 0 - CID=30F0540BCC44  
2024-02-02 14:34:47,059 DTLSConnector        [DEBUG] 1 left recent handshakes, 0 removed in 0ms!  
2024-02-02 14:34:52,059 DTLSConnector        [TRACE] 1 recent handshakes, cleaning up 0 - CID=30F0540BCC44  
2024-02-02 14:34:52,060 DTLSConnector        [DEBUG] 1 left recent handshakes, 0 removed in 0ms!  
2024-02-02 14:34:54,884 ClientServlet        [WARN] Unexpected exception  
java.lang.NullPointerException: null
    at org.eclipse.leshan.server.request.DefaultDownlinkRequestSender.send(DefaultDownlinkRequestSender.java:93)
    at org.eclipse.leshan.server.queue.QueueModeLwM2mRequestSender.send(QueueModeLwM2mRequestSender.java:60)
    at org.eclipse.leshan.server.LeshanServer.send(LeshanServer.java:477)
    at org.eclipse.leshan.server.LeshanServer.send(LeshanServer.java:450)
    at org.eclipse.leshan.server.demo.servlet.ClientServlet.doGet(ClientServlet.java:252)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:554)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
    at org.eclipse.jetty.server.Server.handle(Server.java:516)
    at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487)
    at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
    at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
    at java.base/java.lang.Thread.run(Thread.java:829)
2024-02-02 14:34:57,045 SweepDeduplicator    [TRACE] Start Mark-And-Sweep with 0 entries  
2024-02-02 14:34:57,054 SweepDeduplicator    [TRACE] Start Mark-And-Sweep with 1 entries  
2024-02-02 14:34:57,054 SweepDeduplicator    [DEBUG] Sweep run took 0ms  
2024-02-02 14:34:57,060 DTLSConnector        [TRACE] 1 recent handshakes, cleaning up 0 - CID=30F0540BCC44  
2024-02-02 14:34:57,061 DTLSConnector        [DEBUG] 1 left recent handshakes, 0 removed in 0ms!  
2024-02-02 14:35:02,061 DTLSConnector        [TRACE] 1 recent handshakes, cleaning up 0 - CID=30F0540BCC44  
2024-02-02 14:35:02,062 DTLSConnector        [DEBUG] 1 left recent handshakes, 0 removed in 0ms!  
sbernard31 commented 9 months ago

Hi, Thx for reporting this. :pray:

My guess is there is something which doesn't match about the endpoint URI. But as I will not be able to reproduce it, so I will try to add some logs so we will maybe see clearer.

I let you know when I have something you can use to reproduce.

sbernard31 commented 9 months ago

I created a new branch unknown_endpoint about that. (code is in commit 3388cf813780f6c9276dff32cd9d6a9cc3396d2f)

Is it easy for you to test just like this ? (I mean do you already build Leshan?)

leandrolanzieri commented 9 months ago

Thanks. Here are the new logs. I think there may be something wrong when defining the interface of the endpoint at which the node registered itself, because then it can't be match to the actual ones.

024-02-02 18:37:00,164 ClientServlet        [WARN] Unexpected exception  
java.lang.IllegalStateException: Client testRIOTDevice register itself to coaps://[fe80:0:0:0:6098:a7ff:fed9:3cea%2533]:5684 endpoint, but it seems there is no available endpoints identified byt this URI.
Available endpoints are : 
coap://[fe80:0:0:0:6098:a7ff:fed9:3cea%33]:5683
coaps://[fe80:0:0:0:6098:a7ff:fed9:3cea%33]:5684
coap://[0:0:0:0:0:0:0:0]:5685
    at org.eclipse.leshan.server.request.DefaultDownlinkRequestSender.getEndpoint(DefaultDownlinkRequestSender.java:165)
    at org.eclipse.leshan.server.request.DefaultDownlinkRequestSender.send(DefaultDownlinkRequestSender.java:89)
    at org.eclipse.leshan.server.queue.QueueModeLwM2mRequestSender.send(QueueModeLwM2mRequestSender.java:60)
    at org.eclipse.leshan.server.LeshanServer.send(LeshanServer.java:477)
    at org.eclipse.leshan.server.LeshanServer.send(LeshanServer.java:450)
    at org.eclipse.leshan.server.demo.servlet.ClientServlet.doGet(ClientServlet.java:252)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:687)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
    at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799)
    at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:554)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
    at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233)
    at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188)
    at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505)
    at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594)
    at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186)
    at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355)
    at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
    at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127)
    at org.eclipse.jetty.server.Server.handle(Server.java:516)
    at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487)
    at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732)
    at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479)
    at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
    at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:338)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
    at java.base/java.lang.Thread.run(Thread.java:1583)
2024-02-02 18:37:01,529 DTLSConnector        [TRACE] 1 recent handshakes, cleaning up 0 - CID=D83431010328  
2024-02-02 18:37:01,530 DTLSConnector        [DEBUG] 1 left recent handshakes, 0 removed in 0ms!  
2024-02-02 18:37:06,511 SweepDeduplicator    [TRACE] Start Mark-And-Sweep with 0 entries  
2024-02-02 18:37:06,521 SweepDeduplicator    [TRACE] Start Mark-And-Sweep with 1 entries  
2024-02-02 18:37:06,521 SweepDeduplicator    [DEBUG] Sweep run took 0ms  
2024-02-02 18:37:06,530 DTLSConnector        [TRACE] 1 recent handshakes, cleaning up 0 - CID=D83431010328  
2024-02-02 18:37:06,530 DTLSConnector        [DEBUG] 1 left recent handshakes, 0 removed in 0ms!  
2024-02-02 18:37:11,531 DTLSConnector        [TRACE] 1 recent handshakes, cleaning up 0 - CID=D83431010328  
2024-02-02 18:37:11,531 DTLSConnector        [DEBUG] 1 left recent handshakes, 0 removed in 0ms (full)!  
2024-02-02 18:37:16,511 SweepDeduplicator    [TRACE] Start Mark-And-Sweep with 0 entries  
2024-02-02 18:37:16,521 SweepDeduplicator    [TRACE] Start Mark-And-Sweep with 1 entries  
2024-02-02 18:37:16,521 SweepDeduplicator    [DEBUG] Sweep run took 0ms  
2024-02-02 18:37:16,531 DTLSConnector        [TRACE] 1 recent handshakes, cleaning up 0 - CID=D83431010328  
2024-02-02 18:37:16,532 DTLSConnector        [DEBUG] 1 left recent handshakes, 0 removed in 0ms!  
sbernard31 commented 9 months ago

Yep it seems there is something unexpected with :

coaps://[fe80:0:0:0:6098:a7ff:fed9:3cea%2533]:5684 
VS
coaps://[fe80:0:0:0:6098:a7ff:fed9:3cea%33]:5684

I will try to investigate a bit more.

Perhaps, a workaround for you would be to use IPv4 ?

leandrolanzieri commented 9 months ago

Thanks. Unfortunately, IPv4 is currently not an option for me, as most of the networking infrastructure in RIOT is IPv6.

sbernard31 commented 9 months ago

I try to understand the %xxxx part of the ipv6 address in your case. (First finding : https://superuser.com/questions/99746/why-is-there-a-percent-sign-in-the-ipv6-address)

It seems this is relative to local link address, so I guess you should not get same issue when testing with : https://leshan.eclipseprojects.io ? Or ?

leandrolanzieri commented 9 months ago

It is indeed because I'm using link local addresses. It specifies the interface. I'm not able to test with leshan.eclipseprojects.io because I don't see an IPv6 for it. I can try later again by using global addresses, locally.

sbernard31 commented 9 months ago

I'm not able to test with leshan.eclipseprojects.io because I don't see an IPv6 for it. I

I didn't test it recently but I remember that we add an ipv6 address to leshan sandbox : https://github.com/eclipse-leshan/leshan/issues/1210

I just run nslookup and get :

$> nslookup leshan.eclipseprojects.io                                                                                                                                             

Server:     212.27.40.241
Address:    212.27.40.241#53

Non-authoritative answer:
Name:   leshan.eclipseprojects.io
Address: 23.97.187.154
Name:   leshan.eclipseprojects.io
Address: 2a01:111:f100:9001::1761:93fa

Tell what makes you think that ipv6 is not supported ? (maybe it doesn't really work ?)

It is indeed because I'm using link local addresses. It specifies the interface.

Yep I need to understand this better to know how Leshan should behave in this case :thinking:

leandrolanzieri commented 9 months ago

I just run nslookup and get :

Hmm interesting, dig shows only the IPv4 entry:

$ dig leshan.eclipseprojects.io

; <<>> DiG 9.18.21 <<>> leshan.eclipseprojects.io
;; global options: +cmd
;; Got answer:
;; ->>HEADER<<- opcode: QUERY, status: NOERROR, id: 29132
;; flags: qr rd ra; QUERY: 1, ANSWER: 1, AUTHORITY: 0, ADDITIONAL: 1

;; OPT PSEUDOSECTION:
; EDNS: version: 0, flags:; udp: 1232
; COOKIE: bd0b0a7151dc17120100000065c0a8b08967c90c3a868a9b (good)
;; QUESTION SECTION:
;leshan.eclipseprojects.io. IN  A

;; ANSWER SECTION:
leshan.eclipseprojects.io. 85383 IN A   23.97.187.154

;; Query time: 10 msec
;; SERVER: 131.169.40.200#53(131.169.40.200) (UDP)
;; WHEN: Mon Feb 05 10:21:52 CET 2024
;; MSG SIZE  rcvd: 98

I'll give it a try later

sbernard31 commented 9 months ago

Ok It's still not crystal clear to me how Leshan should behave with zone id but I understand this should be more or less transparent.

The question remaining is why we get %2533 on one side and %33 on the other side... :thinking:

In Leshan we have 2 ways to create the endpoint URI :

Looking at : https://www.rfc-editor.org/rfc/rfc6874#section-2, we can read :

In a URI, a literal IPv6 address is always embedded between "[" and "]". This document specifies how a can be appended to the address. According to URI syntax [RFC3986], "%" is always treated as an escape character in a URI, so, according to the established URI syntax [RFC3986] any occurrences of literal "%" symbols in a URI MUST be percent-encoded and represented in the form "%25". Thus, the scoped address fe80::a%en1 would appear in a URI as http://[fe80::a%25en1].

and :

 IP-literal = "[" ( IPv6address / IPv6addrz / IPvFuture  ) "]"

 ZoneID = 1*( unreserved / pct-encoded )

IPv6addrz = IPv6address "%25" ZoneID

I understand the right way should be to use %25 in URI. :thinking: I will try to adapt the code.

sbernard31 commented 9 months ago

I created a PR to try to fix that : #1581.

Could you test it and tell me if it fix your issue. :pray:

leandrolanzieri commented 9 months ago

Could you test it and tell me if it fix your issue. 🙏

it works!

sbernard31 commented 9 months ago

it works!

Great :tada:

Thx a lot for your help :pray:

I will integrate this soon in master, unless you want more time to play with it and maybe provide more feedback ?

sbernard31 commented 9 months ago

I gonna integrate https://github.com/eclipse-leshan/leshan/pull/1581 in master. The fix should be available in next release 2.0.0-M15.