JSONParserGeneratorRK (0.1.3) and OS 2.0.0

Firmware
1

problem: recently updated to OS 2.0.0 with JSONParserGeneratorRK(0.1.3) and I’m having trouble grabbing the key “name” from the “hook-response/InitialParamWrite” getKeyHandler publish event. As you can see in the picture, my Integration is working correctly, doing the initial write and firing the webhook response but it’s like my getKeyHandler function never fires… in my logs, I get the TWO log-info from InitialParametersWrite() but never get the Log.info from getKeyHandler.

I’m not sure what to try at this point, any guidance would be appreciated.

thanks,
Brian

    Particle.subscribe("hook-response/InitialParamsWrite", getKeyHandler);

void InitialParametersWrite() {


    char qPP[512];
    
    snprintf(qPP, sizeof(qPP), "{\"key\":\"%s\",\"ndex\":%d,\"Cyc\":%d,\"PB\":%d,\"PMode\":%d,\"PTog\":%.1f,\"Td\":%d,\"Ti\":%d,\"fan\":%s,\"ign\":%s,\"aug\":%s,\"mode\":\"%s\",\"pgm\":%s,\"target\":%d,\"u\":%.2f,\"n\":\"%s\"}",
             controller, ndex, Cyc, PB, PMode, PTog, Td, Ti, fan ? "true" : "false", ign ? "true" : "false", aug ? "true" : "false", mode, pgm ? "true" : "false", target, u, deviceName.c_str());

    Particle.publish(INITIAL_PARAMS_WRITE, qPP, 60, PRIVATE);
    // remember this publish event triggers the web-hook response for the parameters Key that is returned from Firebase... so very important!
    Log.info("%s %.3f InitialParametersWrite: c:%s ndex:%d C:%d PB:%d PM:%d PT:%.0f Td:%d Ti:%d\r\n", Time.timeStr().c_str(), getTimeWithMillis(), controller, ndex, Cyc, PB, PMode, PTog, Td, Ti);
    Log.info("%s %.3f InitialParametersWrite: F:%s I:%s A:%s M:%s Pg:%s TT:%d u:%.2f\r\n", Time.timeStr().c_str(), getTimeWithMillis(), fan ? "true" : "false", ign ? "true" : "false", aug ? "true" : "false", mode, pgm ? "true" : "false", target, u);

}


void getKeyHandler(const char *event, const char *data) {
    JsonParserStatic<32, 60> keyParser;
    keyParser.clear();
    keyParser.addString(data);
    
    String newKey;
    keyParser.getOuterValueByKey("name", newKey);
    strcpy(key, newKey);
    strcpy(postKey, newKey);
    Log.info("%s %.3f getKeyhandler: Parameters key from Parameters write web-hook:[%s]. postkey is:[%s]", Time.timeStr().c_str(), getTimeWithMillis(), key, postKey);
}

events_log
events_log1582×232 32.6 KB

1 Like
2

When the key handler never fires it’s little to do with JSONParserGeneratorRK I’d say.

Could it be that your Particle.subscribe() call happens to late and hence never gets registered with the cloud?

BTW, when you use INITIAL_PARAMS_WRITE as a placeholder for your event name it would be good to also have the subscribe filter being derived from that.
Otherwise at a later date you may decide to change INITIAL_PARAMS_WRITE but wonder why the subscription doesn’t follow that change.

3

In your Webhook integration, open the Advanced Settings and check the Response Topic:

Screen Shot 2020-12-11 at 6.25.09 AM
Screen Shot 2020-12-11 at 6.25.09 AM1524×618 17.2 KB

If it looks like that, with {{PARTICLE_DEVICE_ID}} in it, you need to subscribe like this:

Particle.subscribe(System.deviceID() + "/hook-response/InitialParamsWrite", getKeyHandler);
1 Like
4

The subscription filter and the response name seem to be correct tho’
image

Hence my feeling that the subscription may happen after the registration window has closed by the time the subscribe call is made.

However, since we don’t see the entire code it might also just be a SerialLogHandler that’s not configured correctly to show Log.info() output from within the subscription callback.
Can you try Serial.printlnf() instead?

5

This is no longer a problem since Device OS 2.0. Changes in subscriptions at any point in time will trigger a message to notify the cloud. See https://github.com/particle-iot/device-os/pull/2024 for the information about these changes.

2 Likes
6

Good to know :+1: - but unfortunate in this case as we need to find another explanation :wink:

1 Like
7

Thanks all for your help. @ScruffR, I did the Serial.printlnf() to PUTTY serial… got my messages from SETUP() to show fine in the terminal… but NO messages came from the Serial.printlnf() that I placed in getKeyHandler.

@rickkas7, I tried the “Reponse Topic” entry. It was empty in my integration, so I entered what you have above and modified my subscribe… I saw the webhook response concatenated with my PARTICLE_DEVICE_ID in the event log, as expected, but getKeyHandler still does not appear to be getting called.

8

Any chance you can share your code (e.g. via PM and Web IDE SHARE THIS REVISION) and sanitised Webhook definition?

9

And just to be sure, the device is claimed to an account, correct?

Unclaimed devices cannot subscribe to any events. Unclaimed product devices can send events and trigger product webhooks, but cannot receive a response.

11

ok @ScruffR sent you a link via PM

12

yes, it is claimed to my particle account.

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
14

The behavior of Particle.subscribe() in AUTOMATIC mode has changed in 2.0.0 and the subscriptions are now sent to the cloud when the application returns from setup() – along with the list of registered functions and variables.

In general, regardless of Device OS version, calling Particle.subscribe() before Particle.publish() in the code doesn’t guarantee that the subscription will be actually registered on the cloud before the cloud has received the published event. The packet carrying the subscription info may get reordered, or lost and retransmitted after a timeout. The server may also take some indeterminate time to fully process the subscription request.

15

I don’t think this behaviour is documented (clearly enough - if at all).
Especially the part that subscriptions will not become effective before setup() has ended needs a very clear heads-up IMHO.
The docs do state this

image
image778×278 23.8 KB

but don’t mention anything about the fact that limitation with regards to setup() not having ended.

Additionally, particularly confusing seems the fact that this behaviour does appear to be non-consistend - i.e. "particle/...." subscriptions appear to be registered even before setup() ended.

Your note about “reordering packets” seems to address an edge case where the registration of the subscription and the publishing of the event happen in close temporal proximity but with a 5 second delay between the two this seems highly unlikely to me as I’d not be content with the device OS holding off from sending my packets for that long without good (documented) reason.

Given the confusion this change has caused in this case (who knows who else’s existing code will be affected by this change in behaviour) it might be worth considering to hold off from publishing “user” events till subscriptions are actually registered.
Having a device do some things as expected but very similar things completely different seems a rather subpar UX.

16

I don’t think this behaviour is documented

You’re right. It looks like we updated the docs for Particle.variable() and Particle.function() but not for Particle.subscribe().

Additionally, particularly confusing seems the fact that this behaviour does appear to be non-consistend - i.e. “particle/…” subscriptions appear to be registered even before setup() ended.

It may be just that the cloud already has some of the subscriptions, e.g. if the device’s cloud session was resumed. Also, particle/... events are reserved for internal use. I don’t think there has to be consistency in regards to how those events are handled vs application events.

Your note about “reordering packets” seems to address an edge case where the registration of the subscription and the publishing of the event happen in close temporal proximity but with a 5 second delay between the two this seems highly unlikely to me as I’d not be content with the device OS holding off from sending my packets for that long without good (documented) reason.

It’s not an edge case. UDP is an unreliable protocol and any packet may be lost during transmission. IIRC, the initial retransmission timeout for CoAP messages in Device OS is 4 secods plus some random adjustment which together can be longer than 5 seconds from your example. Again, until there’s a way to track completion of Particle.subscribe(), it’s generally unsafe to assume a particular order of the registration of the event subscriptions in your application code.

1 Like
17

But that difference is not obvious for the user who calls the same function only with some different string parameter - that might be another point that wants better documentation for Particle.subscribe().

Again, since the actual behaviour is (IMO) not clearly documented the fact that one kind of subscription did render the correct result but the other didn’t is very confusing and hard to make sense of without a ton of internal background info and/or assumptions.
Neither of both should be required to write reliable and/or debug misbehaving code :wink:

3 Likes
18

Hi @ScruffR and @sergey, what is the solution to get round this issue exactly? After upgrading to v2.0.0 we are now finding many problems with subscribe handlers not being called.

We are using SYSTEM_MODE(SEMI_AUTOMATIC) and SYSTEM_THREAD(ENABLED).
In setup(), publishing the device ID and co-ordinates works fine, but the response does not get picked up by the device anymore. From reading the above, I have tried delaying for 5s between subscribing and publishing, and then it waits for a further 40s to receive the response. I can see from the integration that the response comes back within a couple of seconds, but for some reason the device handler isn’t getting called anymore!

19

The issue discussed in this topic is specific to the AUTOMATIC mode, so it must be something else in your case.

20

Have you tried registering the subscriptions on the device before actually connecting to the cloud?
I’d even suggest to keep the subscription registration in setup() even when putting the rest of the (re)connection logic elsewhere.

1 Like
21

I did think that may have been the issue so tried explicitly disconnecting beforehand:

if (WiFi.ready())
{
  if(Particle.connected()){
    Particle.disconnect();
    waitUntil(Particle.disconnected);
  }
  // we must register subscriptions before Particle.connect?
  setupParticleResponses();
  Particle.connect();
  if(waitFor(Particle.connected, 5s)) delay(5s);
}

But alas, same problem occurs, here is the log:

Dec 16 16:33:48 3f0024000647373336323230 [system] INFO: Cloud: disconnecting
Dec 16 16:33:48 3f0024000647373336323230 [system] INFO: Cloud: disconnected
Dec 16 16:33:48 3f0024000647373336323230 [app] TRACE: setupParticleResponses() success
Dec 16 16:33:49 3f0024000647373336323230 [system] INFO: Cloud: connecting
Dec 16 16:33:49 3f0024000647373336323230 [system] INFO: Cloud socket connected
Dec 16 16:33:49 3f0024000647373336323230 [comm.protocol.handshake] INFO: Establish secure connection
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol.handshake] INFO: Sending HELLO message
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol.handshake] INFO: Receiving HELLO response
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol] INFO: waiting 4 seconds for message type=0
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol] TRACE: rcv'd message type=0
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol.handshake] INFO: Handshake completed
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol] INFO: Posting 'S' describe message
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol] INFO: Posting 'A' describe message
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol] INFO: Sending subscriptions
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol] TRACE: Reply recieved: type=2, code=0
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol] TRACE: message id 23340 complete with code 0.00
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol] TRACE: rcv'd message type=13
Dec 16 16:33:50 3f0024000647373336323230 [system] INFO: Cloud connected
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol] TRACE: Reply recieved: type=2, code=69
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol] TRACE: message id 23345 complete with code 2.05
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol] INFO: Received TIME response: 1608136430
Dec 16 16:33:50 3f0024000647373336323230 [comm.protocol] TRACE: rcv'd message type=12
Dec 16 16:33:51 3f0024000647373336323230 [comm.protocol] TRACE: Reply recieved: type=2, code=0
Dec 16 16:33:51 3f0024000647373336323230 [comm.protocol] TRACE: message id 23346 complete with code 0.00
Dec 16 16:33:51 3f0024000647373336323230 [comm.protocol] TRACE: rcv'd message type=13
Dec 16 16:33:51 3f0024000647373336323230 [comm.protocol] TRACE: Reply recieved: type=2, code=0
Dec 16 16:33:51 3f0024000647373336323230 [comm.protocol] TRACE: message id 23347 complete with code 0.00
Dec 16 16:33:51 3f0024000647373336323230 [comm.protocol] TRACE: rcv'd message type=13
Dec 16 16:33:51 3f0024000647373336323230 [comm.protocol] TRACE: Reply recieved: type=2, code=0
Dec 16 16:33:51 3f0024000647373336323230 [comm.protocol] TRACE: message id 23348 complete with code 0.00
Dec 16 16:33:51 3f0024000647373336323230 [comm.protocol] TRACE: rcv'd message type=13
Dec 16 16:33:51 3f0024000647373336323230 [comm.protocol] TRACE: rcv'd message type=8
Dec 16 16:33:52 3f0024000647373336323230 [comm.protocol] INFO: Received DESCRIBE request; flags: 0x04
Dec 16 16:33:52 3f0024000647373336323230 [comm.protocol] INFO: Posting 'M' describe message
Dec 16 16:33:52 3f0024000647373336323230 [comm.protocol] TRACE: rcv'd message type=1
Dec 16 16:33:53 3f0024000647373336323230 [comm.protocol] TRACE: Reply recieved: type=2, code=0
Dec 16 16:33:53 3f0024000647373336323230 [comm.protocol] TRACE: message id 23349 complete with code 0.00
Dec 16 16:33:53 3f0024000647373336323230 [comm.protocol] TRACE: rcv'd message type=13
Dec 16 16:33:56 3f0024000647373336323230 [comm.protocol] TRACE: Reply recieved: type=2, code=0
Dec 16 16:33:56 3f0024000647373336323230 [comm.protocol] TRACE: message id 23350 complete with code 0.00
Dec 16 16:33:56 3f0024000647373336323230 [comm.protocol] TRACE: rcv'd message type=13
Dec 16 16:33:56 3f0024000647373336323230 [app] TRACE: Memory available = 38792 bytes
Dec 16 16:34:11 3f0024000647373336323230 [comm.protocol] TRACE: Reply recieved: type=2, code=0
Dec 16 16:34:11 3f0024000647373336323230 [comm.protocol] TRACE: message id 23352 complete with code 0.00
Dec 16 16:34:11 3f0024000647373336323230 [comm.protocol] TRACE: rcv'd message type=13
Dec 16 16:34:26 3f0024000647373336323230 [comm.protocol] TRACE: Reply recieved: type=2, code=0
Dec 16 16:34:26 3f0024000647373336323230 [comm.protocol] TRACE: message id 23354 complete with code 0.00
Dec 16 16:34:26 3f0024000647373336323230 [comm.protocol] TRACE: rcv'd message type=13
Dec 16 16:34:41 3f0024000647373336323230 [comm.protocol] TRACE: Reply recieved: type=2, code=0
Dec 16 16:34:41 3f0024000647373336323230 [comm.protocol] TRACE: message id 23355 complete with code 0.00
Dec 16 16:34:41 3f0024000647373336323230 [comm.protocol] TRACE: rcv'd message type=13
Dec 16 16:34:51 3f0024000647373336323230 [app] ERROR: Failed getting configuration