search

eclipse-californium / californium

CoAP/DTLS Java Implementation
https://www.eclipse.org/californium/
Other
729 stars 367 forks source link

Observable resources throw StackOverflowErrors after some time #1030

Closed HeikoBornholdt closed 5 years ago

HeikoBornholdt commented 5 years ago

I am using Californium version 1.0.7 and have a problem with an observable resource. After the number of n responses, they throw a StackOverflowError (n is about the stack size).

Here is a minimal example:

package city.sane.wot.examples;

import org.eclipse.californium.core.CoapResource;
import org.eclipse.californium.core.CoapServer;
import org.eclipse.californium.core.coap.CoAP;
import org.eclipse.californium.core.server.resources.CoapExchange;

public class MyObservableResource extends CoapResource {
    private int i = 0;

    public MyObservableResource(String name) {
        super(name);
        setObservable(true); // enable observing
        setObserveType(CoAP.Type.CON); // configure the notification type to CONs
        getAttributes().setObservable(); // mark observable in the Link-Format
    }

    @Override
    public void handleGET(CoapExchange exchange) {
            // send acknowledgement
            exchange.accept();

            try {
                Thread.sleep(50);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }

            i = i + 1;

            exchange.respond(Integer.valueOf(i).toString());
            changed();
    }

    public static void main(String[] args) {
        CoapServer server = new CoapServer();
        server.add(new MyObservableResource("hello"));
        server.start();
    }
}

And here is the resulting shortenend stacktrace:

Aug. 08, 2019 6:59:04 NACHM. org.eclipse.californium.core.network.config.NetworkConfig createStandardWithFile
INFO: Loading standard properties from file Californium.properties
Aug. 08, 2019 6:59:05 NACHM. org.eclipse.californium.core.CoapServer start
INFO: Starting server
Aug. 08, 2019 6:59:05 NACHM. org.eclipse.californium.core.CoapServer start
INFO: No endpoints have been defined for server, setting up server endpoint on default port 5683
Aug. 08, 2019 6:59:05 NACHM. org.eclipse.californium.core.network.CoapEndpoint start
INFO: Starting endpoint at 0.0.0.0/0.0.0.0:5683
Aug. 08, 2019 6:59:08 NACHM. org.eclipse.californium.core.CoapResource addObserveRelation
INFO: Successfully established observe relation between /127.0.0.1:63880#de71190f and resource /hello
Aug. 08, 2019 7:00:17 NACHM. org.eclipse.californium.core.network.CoapEndpoint$5 run
SEVERE: Exception in protocol stage thread: null
java.lang.StackOverflowError
    at java.base/java.util.Locale.isUnicodeExtensionKey(Locale.java:2244)
    at java.base/java.util.Locale.getUnicodeLocaleType(Locale.java:1315)
    at java.base/sun.util.locale.provider.CalendarDataUtility.findRegionOverride(CalendarDataUtility.java:135)
    at java.base/java.text.DecimalFormatSymbols.initialize(DecimalFormatSymbols.java:619)
    at java.base/java.text.DecimalFormatSymbols.<init>(DecimalFormatSymbols.java:113)
    at java.base/sun.util.locale.provider.DecimalFormatSymbolsProviderImpl.getInstance(DecimalFormatSymbolsProviderImpl.java:85)
    at java.base/java.text.DecimalFormatSymbols.getInstance(DecimalFormatSymbols.java:180)
    at java.base/java.util.Formatter.getZero(Formatter.java:2437)
    at java.base/java.util.Formatter.<init>(Formatter.java:1956)
    at java.base/java.util.Formatter.<init>(Formatter.java:1978)
    at java.base/java.lang.String.format(String.java:2897)
    at org.eclipse.californium.core.coap.CoAP$ResponseCode.toString(CoAP.java:277)
    at java.base/java.util.Formatter$FormatSpecifier.printString(Formatter.java:3031)
    at java.base/java.util.Formatter$FormatSpecifier.print(Formatter.java:2908)
    at java.base/java.util.Formatter.format(Formatter.java:2673)
    at java.base/java.util.Formatter.format(Formatter.java:2609)
    at java.base/java.lang.String.format(String.java:2897)
    at org.eclipse.californium.core.coap.Response.toString(Response.java:89)
    at java.base/java.lang.String.valueOf(String.java:2951)
    at java.base/java.lang.StringBuilder.append(StringBuilder.java:168)
    at org.eclipse.californium.core.network.stack.ReliabilityLayer.sendResponse(ReliabilityLayer.java:160)
    at org.eclipse.californium.core.network.stack.AbstractLayer.sendResponse(AbstractLayer.java:68)
    at org.eclipse.californium.core.network.stack.BlockwiseLayer.sendResponse(BlockwiseLayer.java:302)
    at org.eclipse.californium.core.network.stack.AbstractLayer.sendResponse(AbstractLayer.java:68)
    at org.eclipse.californium.core.network.stack.ObserveLayer.sendResponse(ObserveLayer.java:111)
    at org.eclipse.californium.core.network.stack.AbstractLayer.sendResponse(AbstractLayer.java:68)
    at org.eclipse.californium.core.network.stack.CoapStack$StackTopAdapter.sendResponse(CoapStack.java:173)
    at org.eclipse.californium.core.network.stack.CoapStack.sendResponse(CoapStack.java:120)
    at org.eclipse.californium.core.network.CoapEndpoint.sendResponse(CoapEndpoint.java:413)
    at org.eclipse.californium.core.network.Exchange.sendResponse(Exchange.java:219)
    at org.eclipse.californium.core.server.resources.CoapExchange.respond(CoapExchange.java:290)
    at org.eclipse.californium.core.server.resources.CoapExchange.respond(CoapExchange.java:211)
    at org.eclipse.californium.core.server.resources.CoapExchange.respond(CoapExchange.java:192)
    at city.sane.wot.examples.MyObservableResource.handleGET(MyObservableResource.java:44)
    at org.eclipse.californium.core.CoapResource.handleRequest(CoapResource.java:212)
    at org.eclipse.californium.core.observe.ObserveRelation.notifyObservers(ObserveRelation.java:137)
    at org.eclipse.californium.core.CoapResource.notifyObserverRelations(CoapResource.java:763)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:744)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:725)
    at city.sane.wot.examples.MyObservableResource.handleGET(MyObservableResource.java:45)
    at org.eclipse.californium.core.CoapResource.handleRequest(CoapResource.java:212)
    at org.eclipse.californium.core.observe.ObserveRelation.notifyObservers(ObserveRelation.java:137)
    at org.eclipse.californium.core.CoapResource.notifyObserverRelations(CoapResource.java:763)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:744)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:725)
    ...
    at city.sane.wot.examples.MyObservableResource.handleGET(MyObservableResource.java:45)
    at org.eclipse.californium.core.CoapResource.handleRequest(CoapResource.java:212)
    at org.eclipse.californium.core.observe.ObserveRelation.notifyObservers(ObserveRelation.java:137)
    at org.eclipse.californium.core.CoapResource.notifyObserverRelations(CoapResource.java:763)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:744)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:725)
    at city.sane.wot.examples.MyObservableResource.handleGET(MyObservableResource.java:45)
    at org.eclipse.californium.core.CoapResource.handleRequest(CoapResource.java:212)
    at org.eclipse.californium.core.observe.ObserveRelation.notifyObservers(ObserveRelation.java:137)
    at org.eclipse.californium.core.CoapResource.notifyObserverRelations(CoapResource.java:763)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:744)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:725)
    at city.sane.wot.examples.MyObservableResource.handleGET(MyObservableResource.java:45)
boaks commented 5 years ago

at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:725) at city.sane.wot.examples.MyObservableResource.handleGET(MyObservableResource.java:45)

Calling "changed" triggers the coap-resource to execute the observer GET-exchange again. That causes the recursion and so the stackoverflow. I'm not sure, why the GET itself changes the Resource. To escape the stackoverflow you may try to run the changed in a Runnable executed with CoapResource.execute(Runnable task).

boaks commented 5 years ago

I am using Californium version 1.0.7

If possible, please use the master (2.0.x, SNAPSHOT or 2.0.0-M16).

HeikoBornholdt commented 5 years ago

The problem persists also in version 2.0.0-M16. What is new is that the client gets only a fraction of the answers. The protocol says that the messages are postponed.

00:41:00.394 [main] INFO org.eclipse.californium.core.network.config.NetworkConfig - loading properties from file /Users/heiko/Library/Mobile Documents/com~apple~CloudDocs/Wichtig/50Geschäftlich/Wissenschaftlicher Mitarbeiter VSIS 2017/Projekte/SANE/sane-node/Californium.properties
00:41:00.460 [main] INFO org.eclipse.californium.core.CoapServer - Starting server
00:41:00.495 [main] INFO org.eclipse.californium.core.CoapServer - no endpoints have been defined for server, setting up server endpoint on default port 5683
00:41:00.505 [main] INFO org.eclipse.californium.core.network.RandomTokenGenerator - using tokens of 8 bytes in length
00:41:00.562 [main] INFO org.eclipse.californium.core.network.CoapEndpoint - CoapEndpoint uses udp plain
00:41:00.590 [main] INFO org.eclipse.californium.core.network.stack.BlockwiseLayer - BlockwiseLayer uses MAX_MESSAGE_SIZE=1024, PREFERRED_BLOCK_SIZE=512, BLOCKWISE_STATUS_LIFETIME=600000, MAX_RESOURCE_BODY_SIZE=8192, BLOCKWISE_STRICT_BLOCK2_OPTION=false
00:41:00.597 [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
00:41:00.604 [main] DEBUG org.eclipse.californium.core.network.CoapEndpoint - Starting endpoint at coap://0.0.0.0:5683
00:41:00.610 [main] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - no MessageIdProvider set, using default org.eclipse.californium.core.network.InMemoryMessageIdProvider
00:41:00.638 [main] INFO org.eclipse.californium.elements.UDPConnector - UDPConnector starts up 1 sender threads and 1 receiver threads
00:41:00.651 [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]]
00:41:00.653 [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]]
00:41:00.653 [main] INFO org.eclipse.californium.elements.UDPConnector - UDPConnector listening on 0.0.0.0/0.0.0.0:5683, recv buf = 65507, send buf = 65507, recv packet size = 2048
00:41:00.654 [main] INFO org.eclipse.californium.core.network.CoapEndpoint - Started endpoint at coap://0.0.0.0:5683
00:41:04.662 [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 15 bytes from /127.0.0.1:57627
00:41:04.682 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.server.ServerMessageDeliverer - initiating an observe relation between /127.0.0.1:57627 and resource /hello
00:41:04.691 [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 4 bytes to /127.0.0.1:57627
00:41:04.744 [CoapServer(main)#4] INFO org.eclipse.californium.core.CoapResource - successfully established observe relation between /127.0.0.1:57627#A8717C37 and resource /hello (Exchange[R1], size 1)
00:41:04.745 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ReliabilityLayer - Exchange[R1] send response NON-2.05   MID=   -1, Token=null, OptionSet={"Observe":0, "Content-Format":"text/plain"}, "1", failed transmissions: 0
00:41:04.753 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - Exchange[R1] added with generated mid KeyMID[32554, [7f000001]:57627], NON-2.05   MID=32554, Token=A8717C37, OptionSet={"Observe":0, "Content-Format":"text/plain"}, "1"
00:41:04.754 [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 12 bytes to /127.0.0.1:57627
00:41:04.809 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ReliabilityLayer - Exchange[R1] send response CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":1, "Content-Format":"text/plain"}, "2", failed transmissions: 0
00:41:04.810 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ReliabilityLayer - Exchange[R1] prepare retransmission for CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":1, "Content-Format":"text/plain"}, "2"
00:41:04.812 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.Exchange - Exchange[R1] removing NON notification: NON-2.05   MID=32554, Token=A8717C37, OptionSet={"Observe":0, "Content-Format":"text/plain"}, "1"
00:41:04.813 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - removing Exchange[R1] for MID KeyMID[32554, [7f000001]:57627]
00:41:04.813 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.Exchange - Exchange[R1] removing all remaining NON-notifications of observe relation with /127.0.0.1:57627
00:41:04.813 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - Exchange[R1] added with generated mid KeyMID[32555, [7f000001]:57627], CON-2.05   MID=32555, Token=A8717C37, OptionSet={"Observe":1, "Content-Format":"text/plain"}, "2"
00:41:04.815 [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 13 bytes to /127.0.0.1:57627
00:41:04.815 [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 4 bytes from /127.0.0.1:57627
00:41:04.868 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":2, "Content-Format":"text/plain"}, "3"
00:41:04.922 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":3, "Content-Format":"text/plain"}, "4"
...
00:41:09.912 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":96, "Content-Format":"text/plain"}, "97"
00:41:09.964 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":97, "Content-Format":"text/plain"}, "98"
00:41:10.018 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - observe relation check requires the notification to be sent as CON
00:41:10.018 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":98, "Content-Format":"text/plain"}, "99"
00:41:10.070 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":99, "Content-Format":"text/plain"}, "100"
...
00:41:10.555 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":108, "Content-Format":"text/plain"}, "109"
00:41:10.607 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":109, "Content-Format":"text/plain"}, "110"
00:41:10.613 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:41:10.664 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":110, "Content-Format":"text/plain"}, "111"
00:41:10.717 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":111, "Content-Format":"text/plain"}, "112"
...
00:42:00.539 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":1050, "Content-Format":"text/plain"}, "1051"
00:42:00.593 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":1051, "Content-Format":"text/plain"}, "1052"
00:42:00.606 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore.health - MessageExchangeStore contents: 1 exchanges by MID, 0 exchanges by token, 1 MIDs, 
00:42:00.606 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore.health -   KeyMID[32555, [7f000001]:57627], Exchange[R1], retransmission 0, CON-GET    MID=12304, Token=A8717C37, OptionSet={"Observe":0, "Uri-Path":"hello"}, no payload, CON-2.05   MID=32555, Token=A8717C37, OptionSet={"Observe":1, "Content-Format":"text/plain"}, "2"
00:42:00.610 [CoapServer(secondary)#1] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:42:00.646 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":1052, "Content-Format":"text/plain"}, "1053"
00:42:00.699 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":1053, "Content-Format":"text/plain"}, "1054"
...
00:42:07.614 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":1184, "Content-Format":"text/plain"}, "1185"
00:42:07.670 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - a former notification is still in transit. Postponing CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":1185, "Content-Format":"text/plain"}, "1186"
00:42:07.734 [CoapServer(main)#4] ERROR org.eclipse.californium.elements.util.SerialExecutor - unexpected error occurred:
java.lang.StackOverflowError: null
    at org.slf4j.helpers.Util.report(Util.java:122)
    at org.slf4j.helpers.MessageFormatter.safeObjectAppend(MessageFormatter.java:302)
    at org.slf4j.helpers.MessageFormatter.deeplyAppendParameter(MessageFormatter.java:271)
    at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:233)
    at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:173)
    at ch.qos.logback.classic.spi.LoggingEvent.getFormattedMessage(LoggingEvent.java:293)
    at ch.qos.logback.classic.spi.LoggingEvent.prepareForDeferredProcessing(LoggingEvent.java:206)
    at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:223)
    at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
    at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
    at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
    at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
    at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
    at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
    at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:398)
    at ch.qos.logback.classic.Logger.debug(Logger.java:486)
    at org.eclipse.californium.core.network.stack.ObserveLayer.sendResponse(ObserveLayer.java:113)
    at org.eclipse.californium.core.network.stack.AbstractLayer.sendResponse(AbstractLayer.java:74)
    at org.eclipse.californium.core.network.stack.ExchangeCleanupLayer.sendResponse(ExchangeCleanupLayer.java:79)
    at org.eclipse.californium.core.network.stack.BaseCoapStack$StackTopAdapter.sendResponse(BaseCoapStack.java:190)
    at org.eclipse.californium.core.network.stack.BaseCoapStack.sendResponse(BaseCoapStack.java:106)
    at org.eclipse.californium.core.network.CoapEndpoint.sendResponse(CoapEndpoint.java:571)
    at org.eclipse.californium.core.network.Exchange.sendResponse(Exchange.java:370)
    at org.eclipse.californium.core.server.resources.CoapExchange.respond(CoapExchange.java:375)
    at org.eclipse.californium.core.server.resources.CoapExchange.respond(CoapExchange.java:279)
    at org.eclipse.californium.core.server.resources.CoapExchange.respond(CoapExchange.java:257)
    at city.sane.wot.examples.MyObservableResource.handleGET(MyObservableResource.java:31)
    at org.eclipse.californium.core.CoapResource.handleRequest(CoapResource.java:222)
    at org.eclipse.californium.core.observe.ObserveRelation.notifyObservers(ObserveRelation.java:172)
    at org.eclipse.californium.core.CoapResource.notifyObserverRelations(CoapResource.java:839)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:815)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:795)
    at city.sane.wot.examples.MyObservableResource.handleGET(MyObservableResource.java:32)
    at org.eclipse.californium.core.CoapResource.handleRequest(CoapResource.java:222)
    at org.eclipse.californium.core.observe.ObserveRelation.notifyObservers(ObserveRelation.java:172)
    at org.eclipse.californium.core.CoapResource.notifyObserverRelations(CoapResource.java:839)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:815)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:795)
    at city.sane.wot.examples.MyObservableResource.handleGET(MyObservableResource.java:32)
    at org.eclipse.californium.core.CoapResource.handleRequest(CoapResource.java:222)
    at org.eclipse.californium.core.observe.ObserveRelation.notifyObservers(ObserveRelation.java:172)
    at org.eclipse.californium.core.CoapResource.notifyObserverRelations(CoapResource.java:839)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:815)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:795)
    at city.sane.wot.examples.MyObservableResource.handleGET(MyObservableResource.java:32)
    ...
    at org.eclipse.californium.core.CoapResource.handleRequest(CoapResource.java:222)
    at org.eclipse.californium.core.observe.ObserveRelation.notifyObservers(ObserveRelation.java:172)
    at org.eclipse.californium.core.CoapResource.notifyObserverRelations(CoapResource.java:839)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:815)
    at org.eclipse.californium.core.CoapResource.changed(CoapResource.java:795)
    at city.sane.wot.examples.MyObservableResource.handleGET(MyObservableResource.java:32)
    at org.eclipse.californium.core.CoapResource.handleRequest(CoapResource.java:222)
00:42:07.741 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - removing Exchange[R1] for MID KeyMID[32555, [7f000001]:57627]
00:42:07.741 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.UdpMatcher - received expected reply for message KeyMID[32555, [7f000001]:57627]
00:42:07.745 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ReliabilityLayer - Exchange[R1] acknowledge ACK        MID=32555 for response CON-2.05   MID=32555, Token=A8717C37, OptionSet={"Observe":1, "Content-Format":"text/plain"}, "2" (1 msg observer)
00:42:07.746 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ObserveLayer - notification has been acknowledged, send the next one
00:42:07.747 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ReliabilityLayer - Exchange[R1] send response CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":1185, "Content-Format":"text/plain"}, "1186", failed transmissions: 0
00:42:07.747 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.stack.ReliabilityLayer - Exchange[R1] prepare retransmission for CON-2.05   MID=   -1, Token=null, OptionSet={"Observe":1185, "Content-Format":"text/plain"}, "1186"
00:42:07.747 [CoapServer(main)#4] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - Exchange[R1] added with generated mid KeyMID[32556, [7f000001]:57627], CON-2.05   MID=32556, Token=A8717C37, OptionSet={"Observe":1185, "Content-Format":"text/plain"}, "1186"
00:42:07.749 [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 17 bytes to /127.0.0.1:57627
00:42:07.749 [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 4 bytes from /127.0.0.1:57627
00:42:07.750 [CoapServer(main)#1] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore - removing Exchange[R1] for MID KeyMID[32556, [7f000001]:57627]
00:42:07.750 [CoapServer(main)#1] DEBUG org.eclipse.californium.core.network.UdpMatcher - received expected reply for message KeyMID[32556, [7f000001]:57627]
00:42:07.750 [CoapServer(main)#1] DEBUG org.eclipse.californium.core.network.stack.ReliabilityLayer - Exchange[R1] acknowledge ACK        MID=32556 for response CON-2.05   MID=32556, Token=A8717C37, OptionSet={"Observe":1185, "Content-Format":"text/plain"}, "1186" (1 msg observer)
00:42:10.611 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:42:20.614 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:42:30.612 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:42:40.614 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:42:50.614 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:43:00.608 [CoapServer(secondary)#1] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore.health - MessageExchangeStore contents: 0 exchanges by MID, 0 exchanges by token, 1 MIDs, 
00:43:00.610 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:43:10.614 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:43:20.614 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:43:30.612 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:43:40.613 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:43:50.613 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:44:00.610 [CoapServer(secondary)#1] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore.health - MessageExchangeStore contents: 0 exchanges by MID, 0 exchanges by token, 1 MIDs, 
00:44:00.610 [CoapServer(secondary)#1] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:44:10.611 [CoapServer(secondary)#1] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:44:20.613 [CoapServer(secondary)#1] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:44:30.613 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:44:40.614 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:44:50.611 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:45:00.610 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.InMemoryMessageExchangeStore.health - MessageExchangeStore contents: 0 exchanges by MID, 0 exchanges by token, 1 MIDs, 
00:45:00.610 [CoapServer(secondary)#1] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:45:10.615 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
00:45:20.613 [CoapServer(secondary)#2] DEBUG org.eclipse.californium.core.network.deduplication.SweepDeduplicator - Sweep run took 0ms
boaks commented 5 years ago

The problem persists also in version 2.0.0-M16.

:-)

Thought the problem is your code, as I explained in my 1. comment, changing the californium version can not solve the problem. When handleGET calls changed, and changed calls handleGET, it's just a classic recursion, which ends up in an stackoverflow. You may check this fact even outside of californium. Implement f1 { sleep(); f2()} and f2 {f1()} and your stack will overflow after some sleeps.

So read my first comment and try to develop a version with the proposed executed Runnable. If that works, consider to remove the "sleep" and use ScheduledExecutorService instead. In 2.0.0-M16 the CoapResource offers that as getSecondaryExecutor(). Otherwise your next complain will be about "bad performance", but that would also be caused by your code with sleep and not by Californium.

HeikoBornholdt commented 5 years ago

I thought I could do it like this example: https://github.com/eclipse/californium/blob/master/demo-apps/api-demo/src/org/eclipse/californium/examples/CoapObserveExample.java#L67

I have now moved the resource change and the problem is now solved. Thank you very much for your help.