DeviceInfoLedger Config Not Fully Updating

When using the DeviceInfoLedger by @rickkas7 at GitHub - particle-iot/DeviceInfoLedger and following this app note: Reduce on-site support costs by logging data with Particle’s Device Ledger I have found some odd behavior.

I've set the configuration as such underneath the product:
{
"lastRunLog": 1024,
"connectionLog": 8192,
"logAllConnections": true,
"includeGeneral": true,
"includeDiag": true,
"includeTower": true,
"logLevel": "INFO",
"logFilters": {
"app": "INFO",
"app.network": "TRACE",
"ncp.at": "TRACE"
}
}

Devices will pull the configuration, and it will seemingly work, but no connection log will appear, even after several reconnections. The connection log only appears when a device is reset and goes back through setup (calls ::setup() on the ledger).

This link states it should happen very quickly if the device is online, but if its offline it should occur once reconnection happens: Ledger configuration | Getting Started | Particle

Here is what a device's output looks like pre-resetting.

{
"diag": {
"batt:soc": {
"err": -210
},
"batt:state": 0,
"cloud:connatt": 1,
"cloud:dconn": 0,
"cloud:dconnrsn": 2,
"cloud:err": 0,
"cloud:stat": 2,
"coap:retransmit": 10,
"coap:roundtrip": 361,
"coap:transmit": 308,
"coap:unack": 0,
"net:at": 8,
"net:cell:cgi:ci": 194575284,
"net:cell:cgi:lac": 9998,
"net:cell:cgi:mcc": 310,
"net:cell:cgi:mnc": 410,
"net:connatt": 43,
"net:dconn": 0,
"net:dconnrsn": 7,
"net:err": 0,
"net:sigqual": 22399,
"net:sigqualv": -491520,
"net:sigstr": 7039,
"net:sigstrv": -6815744,
"net:stat": 4,
"pub:limit": 0,
"pwr:src": 0,
"sys:protected": 0,
"sys:tram": 149920,
"sys:uptime": 78463,
"sys:uram": 79168
},
"resetReason": 70,
"sysver": "6.2.1",
"tower": {
"cid": 194575284,
"lac": 9998,
"mcc": 310,
"mnc": 410
}
}

Here is what it will look like once reset:
{
"connLog": ": > AT\n0000009254 [ncp.at] TRACE: < OK\n
REDACTED FOR LENGTH SHORTENING
",
"diag": {
"batt:soc": {
"err": -210
},
"batt:state": 0,
"cloud:connatt": 1,
"cloud:dconn": 0,
"cloud:dconnrsn": 0,
"cloud:err": 0,
"cloud:stat": 2,
"coap:retransmit": 1,
"coap:roundtrip": 302,
"coap:transmit": 16,
"coap:unack": 0,
"net:at": 8,
"net:cell:cgi:ci": 196606991,
"net:cell:cgi:lac": 10003,
"net:cell:cgi:mcc": 310,
"net:cell:cgi:mnc": 410,
"net:connatt": 1,
"net:dconn": 0,
"net:dconnrsn": 7,
"net:err": 0,
"net:sigqual": 19199,
"net:sigqualv": -524288,
"net:sigstr": 10879,
"net:sigstrv": -6422528,
"net:stat": 4,
"pub:limit": 0,
"pwr:src": 0,
"sys:protected": 0,
"sys:tram": 149920,
"sys:uptime": 28,
"sys:uram": 99480
},
"resetReason": 70,
"sysver": "6.2.1",
"tower": {
"cid": 196606991,
"lac": 10003,
"mcc": 310,
"mnc": 410
}
}

What initialization lines are you using before setup?

Do you have a local config fallback configured, or are you only relying on the cloud config?

It's not clear to me why it's not working for you. I added a new example 3-tester to version 0.0.4 of the library which has a Particle function to put the device to sleep. I'm getting connLog in Ledger after the device wake up and reconnects to the cloud.

Here is the code added from the app note:

// in global namespace
retained uint8_t retainedLogs[2048];



// in setup
// This sets up remote configuration
    DeviceConfigLedger::instance()
        .withConfigDefaultLedgerName("device-logging-config")
        .setup();

    // This sets up the device information in ledger
    DeviceInfoLedger::instance()
        .withInfoLedgerName("debug-info")
        .withRetainedBuffer(retainedLogs, sizeof(retainedLogs))
        .setup();

// in loop
    DeviceInfoLedger::instance().loop();

I do not have a local config, just the cloud config.

When investigating the cloud ledger, I noticed something unexpected, and wanted to post here to see if it was indicative of the issue.

I have two products that are virtually the same product, one is a dev environment and one is production.

So like this:
PRODUCT_PROD
PRODUCT_DEV

The ledger is in both, with the same name, and Particle recognizes this well. It doesn't work in either environment, and they both have the same settings with connlog on.

The main "device logging config" ledger says last updated 3 days ago, even though the last updated on each individual ledger is very recent.

@rickkas7 seems like Ledger is updating all the values correctly, its just the connLog is messing up for some reason.

One other bit I noticed is odd, is logAllConnections doesn't seem to do anything? It always posts a connection log. I took a look at the source code of the library and it doesn't seem to ever be used. There is a function for retrieving it: getConfigLogAllConnections(), but its never used by the library that I can see.

Am I missing something?

The code currently always treats logAllConnections as being true; there's no way to turn it off, actually. It's a bug, but its working in your favor.

I'd put a logging statement where writeToConnectionLog is set to true. If that's not getting set to true in your failure case, then logging won't start back up again, and the connection log will be empty.

Im using connLog length as a workaround to be able to turn off connLog. From that experiment, another possible failure point is if connLog length was getting set to 0, it behaves the same as I'm seeing in my issue.

I'll dig in and post results later, I'll submit a PR as well if I have a good solution.

Thanks,
Zach

@rickkas7 I printed connectionLogSize, offset, and isCloudConnected, Particle.connected(), and writeToConnectionLog.

I figured out the connectionLogSize never changes, even when getConfigConnectionLog() does. When are you expecting this value to be updated? Seems like there needs to be a point where if that value updates, it updates the LogSize variable.

For a temporary fix which I've tested, I added the following in the loop code (there are better ways of doing this, but it proves the issue):

if(connectionLogSize != getConfigConnectionLog()){
updateConfig();
}

After this, the system works as expected.

That's a bug. Initially the connection log was only used on the first connection, it didn't make a difference if the cloud updated the size. When I switched it to always log, I never took care of the case where the size changed, which now does matter. Thanks for finding that!

Are you seeing the log messages for updateConfig() if you don't call it manually? Those should occur automatically when the ledger is updated from the cloud, which is how the variable gets updated normally.

I'm having trouble seeing the situation where updateConfig would not get called if you have a cloud ledger configured.

Good morning Rick - I'm only seeing the log messages for updateConfig on first boot. I don't see them after that. I'm referring to the quick log statement that shows three variable values.

OK, that explains why it's not working, but I have no idea how that can happen. I'll keep looking. Your workaround will work for now.