NullPointer when a Notification is received while the Registration is being cleaned

[slaft]

Version(s)

2.0.0-M16

Which components

server

Tested With

No response

What happened

I got this log:

WARN org.eclipse.californium.core.network.UdpMatcher error receiving response CON-2.05   MID=54576, Token=29B4C3E33E202B95, OptionSet={"Observe":857, "Content-Format":"text/plain"}, acked "-67" for Exchange...

java.lang.NullPointerException: Cannot invoke "org.eclipse.leshan.server.profile.ClientProfile.getRegistration()" because "profile" is null
	at org.eclipse.leshan.server.observation.ObservationServiceImpl.onError(ObservationServiceImpl.java:255)
	at org.eclipse.leshan.transport.californium.server.endpoint.CaliforniumServerEndpointsProvider$2.onNotification(CaliforniumServerEndpointsProvider.java:179)
	at org.eclipse.californium.core.network.CoapEndpoint$NotificationDispatcher.onNotification(CoapEndpoint.java:811)
	at org.eclipse.californium.core.network.BaseMatcher$2.onResponse(BaseMatcher.java:250)
	at org.eclipse.californium.core.coap.Request.setResponse(Request.java:922)
	at org.eclipse.californium.core.server.ServerMessageDeliverer.deliverResponse(ServerMessageDeliverer.java:280)
	at org.eclipse.californium.core.network.stack.BaseCoapStack$StackTopAdapter.receiveResponse(BaseCoapStack.java:214)
	at org.eclipse.californium.core.network.stack.AbstractLayer.receiveResponse(AbstractLayer.java:89)
	at org.eclipse.californium.core.network.stack.ExchangeCleanupLayer.receiveResponse(ExchangeCleanupLayer.java:105)
	at org.eclipse.californium.core.network.stack.ObserveLayer.receiveResponse(ObserveLayer.java:154)
	at org.eclipse.californium.core.network.stack.BlockwiseLayer.receiveResponse(BlockwiseLayer.java:888)
	at org.eclipse.californium.core.network.stack.ReliabilityLayer.receiveResponse(ReliabilityLayer.java:324)
	at org.eclipse.californium.core.network.stack.AbstractLayer.receiveResponse(AbstractLayer.java:89)
	at org.eclipse.californium.core.network.stack.BaseCoapStack.receiveResponse(BaseCoapStack.java:132)
	at org.eclipse.californium.core.network.CoapEndpoint$1.receiveResponse(CoapEndpoint.java:324)
	at org.eclipse.californium.core.network.UdpMatcher$4.run(UdpMatcher.java:457)
	at org.eclipse.californium.elements.util.SerialExecutor$1.run(SerialExecutor.java:292)
	at org.eclipse.californium.core.network.CoapEndpoint$6.run(CoapEndpoint.java:1367)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
	at java.base/java.lang.Thread.run(Unknown Source)

From my logs:
14:57:34.989 -> the WARN
14:57:35.007 -> RegistrationListener#unregistered() is called with expired = true

It looks like it's the same cause as #1634, the difference is that the Registration is removed after the Observation is retrieved:

leshan/leshan-tl-cf-server-coap/src/main/java/org/eclipse/leshan/transport/californium/server/endpoint/CaliforniumServerEndpointsProvider.java

Lines 156 to 157 in baa124f

	Observation observation = server.getRegistrationStore().getObservation(regid,
	new ObservationIdentifier(coapResponse.getToken().getBytes()));

and before the Registration/ClientProfile is retrieved:

leshan/leshan-tl-cf-server-coap/src/main/java/org/eclipse/leshan/transport/californium/server/endpoint/CaliforniumServerEndpointsProvider.java

Line 165 in baa124f

ClientProfile profile = toolbox.getProfileProvider().getProfile(client.getIdentity());

(We use the RedisRegistrationStore implementation.)

How to reproduce

No response

Relevant Output

No response

[sbernard31]

So I guess it would be better to check if profile is null and do something like what we do for #1634 ?

if (profile == null)
  LOG.warn("Unexpected error: Unable to find registration with id {} for observation {}", regid, coapResponse.getToken());

Let me know if it sounds good to you ?

[slaft]

Yes it seems fine. Thanks.

[sbernard31]

This is done in 18b8147.

If you want to discuss about log level in Leshan : #1641.

Thx @slaft for reporting that 🙏 !