I am getting massive number of following log entries:
07:48:28.409 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 872c34170dbaff31 expected MID 57277 but received 64820
07:48:28.410 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 2552d2 expected MID 2261 but received 64822
07:48:28.413 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 83b1217376d2 expected MID 65025 but received 64829
07:48:28.416 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: e84b expected MID 59603 but received 64830
07:48:28.421 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: fc4b78dd expected MID 58592 but received 64837
07:48:28.423 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: ba0856a95f39 expected MID 5151 but received 64839
07:48:28.428 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: e48c8d4bdd9a expected MID 59438 but received 64840
07:48:28.431 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 98d2a1b2 expected MID 61160 but received 64841
07:48:28.435 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 7e6edc26f85823 expected MID 2182 but received 64842
07:48:28.439 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 062e70fd35775c expected MID 61609 but received 64843
07:48:28.442 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 6d5998abeb2e47 expected MID 64943 but received 64845
07:48:28.445 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 7753e6 expected MID 5811 but received 64847
07:48:28.449 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 8ccc01cb6bd1 expected MID 64769 but received 64849
07:48:28.454 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: aa9f3f897e0b34 expected MID 64592 but received 64851
192.168.3.51 is my TRADFRI GW
2017-09-15 13:46:30.484 [WARN ] [e.californium.scandium.DTLSConnector] - Outbound message queue is full! Dropping outbound message to peer [/192.168.3.51:5684]
2017-09-15 13:46:30.484 [WARN ] [e.californium.scandium.DTLSConnector] - Outbound message queue is full! Dropping outbound message to peer [/192.168.3.51:5684]
2017-09-15 13:46:30.485 [WARN ] [e.californium.scandium.DTLSConnector] - Outbound message queue is full! Dropping outbound message to peer [/192.168.3.51:5684]
Just want to add a “me too”.
Openhabian on Raspberry Pi 3 if that matters.
I also have a RPi 1 running rasbian and also Openhab2.
I have never seen this problem on that one, and they are configures almost the same, on same network connecting to the same Trådfri gateway.
I suddenly observed this one in my logs, too. It appeared directly after removing a device from my gateway without removing it from the OH2 framework. After a little google search I found this issue in the californium library, which has been fixed since couple of days.
2017-10-06 20:57:18.622 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 7e expected MID 62880 but received 62877
2017-10-06 20:57:48.795 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 67 expected MID 972 but received 968
2017-10-06 20:57:51.014 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 2c expected MID 2211 but received 2014
2017-10-06 20:57:51.049 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 7b expected MID 2134 but received 2053
2017-10-06 20:57:51.067 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 55 expected MID 2196 but received 2075
...
Just adding that I have an issue too with different warning. It appeared this morning
RPi 3 with Tradfri gateway and 20 things on the mesh.
2017-11-01 11:08:39.856 [WARN ] [pse.californium.core.network.Matcher] - Possible MID reuse before lifetime end: 2d expected MID 54546 but received 54422
[WARN ] [e.californium.scandium.DTLSConnector] - Outbound message queue is full! Dropping outbound message to peer [/192.168.0.100:5684]
I noticed the gateway patched recently and had a mention that the DTLS setup had changed. The gateway is at v1.2.42. Changelog says ‘…added support for CoAP DTLS sessions…’ I have removed things prior to the patch with no problems, this is the first time (that I am aware of)that I have tried to remove since the patch.
…after dozens of these warnings the system dies and needs a reboot
The log shows the following after attempted removal:
==> /var/log/openhab2/openhab.log <==
2017-11-01 11:23:55.398 [ERROR] [alifornium.core.network.CoapEndpoint] - Exception in protocol stage thread: Illegal status transition from REMOVING to OFFLINE, only REMOVED would have been allowed.
java.lang.IllegalArgumentException: Illegal status transition from REMOVING to OFFLINE, only REMOVED would have been allowed.
at org.eclipse.smarthome.core.thing.internal.ThingManager$1.statusUpdated(ThingManager.java:156)[105:org.eclipse.smarthome.core.thing:0.9.0.b5]
at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateStatus(BaseThingHandler.java:386)[105:org.eclipse.smarthome.core.thing:0.9.0.b5]
at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.updateStatus(BaseThingHandler.java:403)[105:org.eclipse.smarthome.core.thing:0.9.0.b5]
at org.eclipse.smarthome.binding.tradfri.handler.TradfriLightHandler.setStatus(TradfriLightHandler.java:100)[220:org.eclipse.smarthome.binding.tradfri:0.9.0.b5]
at org.eclipse.smarthome.binding.tradfri.internal.TradfriCoapHandler.onLoad(TradfriCoapHandler.java:73)[220:org.eclipse.smarthome.binding.tradfri:0.9.0.b5]
at org.eclipse.californium.core.CoapClient$ObserveMessageObserverImpl.deliver(CoapClient.java:1044)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.CoapClient$MessageObserverImpl.succeeded(CoapClient.java:970)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.CoapClient$MessageObserverImpl.onResponse(CoapClient.java:949)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.coap.Request.setResponse(Request.java:415)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.EndpointManager$ClientMessageDeliverer.deliverResponse(EndpointManager.java:249)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.stack.CoapStack$StackTopAdapter.receiveResponse(CoapStack.java:193)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.stack.AbstractLayer.receiveResponse(AbstractLayer.java:98)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.stack.ObserveLayer.receiveResponse(ObserveLayer.java:138)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.stack.AbstractLayer.receiveResponse(AbstractLayer.java:98)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.stack.BlockwiseLayer.receiveResponse(BlockwiseLayer.java:318)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.stack.AbstractLayer.receiveResponse(AbstractLayer.java:98)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.stack.ReliabilityLayer.receiveResponse(ReliabilityLayer.java:263)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.stack.AbstractLayer.receiveResponse(AbstractLayer.java:98)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.stack.CoapStack.receiveResponse(CoapStack.java:135)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.CoapEndpoint$InboxImpl.receiveMessage(CoapEndpoint.java:630)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.CoapEndpoint$InboxImpl.access$700(CoapEndpoint.java:536)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.CoapEndpoint$InboxImpl$1.run(CoapEndpoint.java:548)[218:californium-osgi:1.0.5]
at org.eclipse.californium.core.network.CoapEndpoint$5.run(CoapEndpoint.java:695)[218:californium-osgi:1.0.5]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)[:1.8.0_121]
at java.util.concurrent.FutureTask.run(FutureTask.java:266)[:1.8.0_121]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)[:1.8.0_121]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)[:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)[:1.8.0_121]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)[:1.8.0_121]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
