JSONParserGeneratorRK (0.1.3) and OS 2.0.0

Firmware
13

Hey Andrey, I have now done some testing with @bbeardmore’s code and it seems to be a race condition.
It may be that you can now register subscriptions late but the problem here is that although the subscriptions were already registered on the device before the publish happens the actual registration with the cloud happens too late.

See this log

0000007973 [system] INFO: Cloud: connecting
0000008247 [system] INFO: Cloud socket connected
0000008247 [comm.protocol.handshake] INFO: Establish secure connection
0000009043 [comm.protocol.handshake] INFO: Sending HELLO message
0000009044 [comm.protocol.handshake] INFO: Receiving HELLO response
0000009044 [comm.protocol] INFO: waiting 4 seconds for message type=0
0000009153 [comm.protocol.handshake] INFO: Handshake completed
0000009167 [comm.protocol] INFO: Posting 'S' describe message
0000009178 [system] INFO: Cloud connected
0000009179 [app] INFO: *************************************** P R O G R A M    B E G I N *******************************************************
0000011200 [comm.protocol] INFO: Received TIME response: 1607800765
0000012200 [app] INFO: Sat Dec 12 14:19:25 2020 1607800765.200 handler: I got the controller name from the particle cloud: [ScruffyBlue]
0000014199 [app] INFO: start Milliseconds is:14199 last3:199 decimal:0.199 logTime:1607800767.199 1607800767
0000014200 [comm.protocol] INFO: Received DESCRIBE request; flags: 0x04
0000014201 [comm.protocol] INFO: Posting 'M' describe message
0000015201 [comm.protocol] INFO: Received DESCRIBE request; flags: 0x02
0000015201 [comm.protocol] INFO: Posting 'A' describe message
0000019200 [app] INFO: **********  //// IN Initial Write Parameters //// **********

Inside InitialParametersWrite()
0000019201 [app] INFO: Sat Dec 12 14:19:33 2020 1607800773.201 InitialParametersWrite: c:ScruffyBlue ndex:0 C:60 PB:60 PM:2 PT:0 Td:45 Ti:180

0000033800 [comm.protocol] INFO: Posting 'A' describe message
0000033800 [comm.protocol] INFO: Sending subscriptions

Just as a long developed habit I moved the subscriptions to the top of setup() before the *** P R O G R A M B E G I N *** log.
Then 19.2 seconds after boot-up the event gets published but the Sending subscriptions log from comm.protocol only happens 33.8 seconds after boot-up.

That seems wrong IMO.

However, when I trigger the event after that the hook-response will be caught just fine.

One thing is puzzling tho’ while this one subscription only works after that Sending subscriptions entry another subscription for spark/ (at 000012200) does fire as expected.

Something is very weird here.

Update:
@avtolstoy, I’ve done some more digging and think I found a pattern.
Unlike the issue (which talks about “soft delay”) linked in the PR you referred us to further up the use of delay() in setup() also seems to cause/contribute to the problem.

With this code

SerialLogHandler serLog(LOG_LEVEL_INFO);

void setup() {
    Particle.subscribe("hook-response/InitialParamsWrite", handleResponse);
    Particle.subscribe("InitialParamsWrite", handleOutgoingEvent);
    Particle.subscribe("particle/device/name", handleName);

    Particle.publish("particle/device/name");
    Particle.publish("InitialParamsWrite"); 
    Particle.publish("particle/device/name");

    Log.info("*** three publishes done - 5 sec cooldonw");
    delay(5000);
    Log.info("*** setup() ends here");
}

void loop() {
    static bool firstRun = true; // false; //
    if (firstRun) {
        firstRun = false;
        Log.info("*** first run of loop()");
        delay(1000);
        Particle.publish("InitialParamsWrite"); 
        delay(1000);
    }
}

void handleResponse(const char* event, const char* data) {
    Log.info("--> Response: %s: %s", event, data);
}

void handleOutgoingEvent(const char* event, const char* data) {
    Log.info("--> Outgoing: %s: %s", event, data);
}

void handleName(const char* event, const char* data) {
    Log.info("--> Name: %s: %s", event, data);
}

I would not expect this log

0000008033 [system] INFO: Cloud: connecting
0000008304 [system] INFO: Cloud socket connected
0000008304 [comm.protocol.handshake] INFO: Establish secure connection
0000009022 [comm.protocol.handshake] INFO: Sending HELLO message
0000009023 [comm.protocol.handshake] INFO: Receiving HELLO response
0000009023 [comm.protocol] INFO: waiting 4 seconds for message type=0
0000009135 [comm.protocol.handshake] INFO: Handshake completed
0000009148 [comm.protocol] INFO: Posting 'S' describe message
0000009159 [system] INFO: Cloud connected
0000009160 [app] INFO: *** three publishes done - 5 sec cooldonw
0000011161 [comm.protocol] INFO: Received TIME response: 1607865422
0000012161 [app] INFO: --> Name: particle/device/name: ScruffyBlue
0000013161 [app] INFO: --> Name: particle/device/name: ScruffyBlue
0000014160 [app] INFO: *** setup() ends here
0000014160 [comm.protocol] INFO: Posting 'A' describe message
0000014161 [comm.protocol] INFO: Sending subscriptions
0000014162 [app] INFO: *** first run of loop()
0000015163 [comm.protocol] INFO: Received DESCRIBE request; flags: 0x04
0000015164 [comm.protocol] INFO: Posting 'M' describe message
0000016162 [comm.protocol] INFO: Received DESCRIBE request; flags: 0x02
0000016163 [comm.protocol] INFO: Posting 'A' describe message
0000017076 [app] INFO: --> Outgoing: InitialParamsWrite: null
0000017077 [app] INFO: --> Response: hook-response/InitialParamsWrite/0: {"name":  "***" }

I’d rather expect to see these two lines twice

0000017076 [app] INFO: --> Outgoing: InitialParamsWrite: null
0000017077 [app] INFO: --> Response: hook-response/InitialParamsWrite/0: {"name":  "***" }

one extra time between these two lines

0000012161 [app] INFO: --> Name: particle/device/name: ScruffyBlue
0000013161 [app] INFO: --> Name: particle/device/name: ScruffyBlue

BTW, even with the firstRun in loop() without the leading delay(1000) the --> Outgoing log is still missing.

1 Like