doseHistory restore from poolState.json

[snagytx]

Hello,

I'm not a TS developer but I can know enough to debug the code. It seems that when the doseHistory is restored from the json file, something is incorrect - all the elements are restored with 0 value.

This is the troubleshooting that I did:

Added a console.log in the DataLoggerEntry constructor as seen in the screenshot:

This is the console.log output:

When it returns to ChemicalDoseState, which calls the above code in the super, the this object is still empty and the element values are not transferred from the extended class:

I'm not really sure why this happens. Maybe this is something basic that I'm missing.

The issue is really easy to reproduce.

1. Ensure that your njPC instance is running for a while and dosing was reported to it.
2. Call http://localhost:4200/state/chemController/1/doseHistory - ensure that you have a few elements in the dosingHistory , it doesn't matter if it's ph or orp.
3. Restart your njPC instance.
4. Call http://localhost:4200/state/chemController/1/doseHistory - you should see correct elements in dosingHistory array - but you don't/

I'm using an IntelliChem as a chemContoller and using the latest source code from git.

This is my ph doseHistory section:

        "doseHistory": [
          {
            "id": 1,
            "method": "auto",
            "start": "2021-10-20T07:56:20.849-0500",
            "end": "2021-10-20T07:57:21.011-0500",
            "chem": "acid",
            "setpoint": 7.5,
            "demand": 0,
            "level": 7.61,
            "volume": 0,
            "status": "completed",
            "volumeDosed": 63,
            "time": 0,
            "timeDosed": 29
          },
          {
            "id": 1,
            "method": "auto",
            "start": "2021-10-20T07:35:52.305-0500",
            "end": "2021-10-20T07:36:50.709-0500",
            "chem": "acid",
            "setpoint": 7.5,
            "demand": 0,
            "level": 7.63,
            "volume": 0,
            "status": "completed",
            "volumeDosed": 67,
            "time": 0,
            "timeDosed": 31
          },
          {
            "id": 1,
            "method": "auto",
            "start": "2021-10-20T07:15:14.146-0500",
            "end": "2021-10-20T07:16:18.650-0500",
            "chem": "acid",
            "setpoint": 7.5,
            "demand": 0,
            "level": 7.64,
            "volume": 0,
            "status": "completed",
            "volumeDosed": 72,
            "time": 0,
            "timeDosed": 33
          }
        ],

[rstrouse]

Just to get me up to speed. What is it returning when you call http://localhost:4200/state/chemController/1/doseHistory? Is it returning an empty object {ph:[], orp:[]} like this? The get call above only returns 24hrs of history and should not be calling the DataLogger object at all.

There is a much more extensive API that filters the chemDosage_acid.log and chemDosage_orp.log files. I am not sure that does much with IntelliChem but will check it out given the fact we don't get any demand numbers for IntelliChem. These api endpoints search the dataLogger files and should not be called using a get verb rather it should be using a search verb. So do not call the endpoint with ph or orp at end.

Please generate a backup and upload it here. You will find the backup functions under the hamburger menu in dashPanel. Also, does the system show the dose history for the last 24 hours in the Chemistry popover.

In your logs directory do you have a chemDosage_acid.log file or a chemDosage_orp.log file? Bear in mind REM chem functionality is much more extensive and tracks a lot more data related to the demand so I am not sure we generate these for IntelliChem.

[snagytx]

This is what the call returns:

And this is how it's in the dashboard:

Please see attached the backup as well:
backup.zip

And this is how the poolState.json looked before I restarted the njPC
poolState.txt

As for the log files, I see that they are generated, but they are not read - I added breakpoints in the code and they don't seem to be read
chemDosage_acid.log
chemDosage_orp.log

[snagytx]

Not relevant here but I think there is a bug because in my setup the code in controller/State.ts

    public set doseHistory(val: ChemicalDoseState[]) {
        this.setDataVal('doseHistory', val);
    }

In never hit, I guess this is not triggered by:

public endDose(dtEnd: Date = new Date(), status: string = 'completed', volumeDosed: number = 0, timeDosed: number = 0): ChemicalDoseState {
...
this.doseHistory.unshift(dose);
...
}

The save of doseHistory is performed when other elements are set/reset

[rstrouse]

No the setter is not called by calling the getter while chaining a this.doseHistory.unshift(dose). The unshift is simply adding a dose to the beginning of the array. We are using proxies for the underlying data so it looks a lot more complicated than it is. This allows us to track changes to the data without beating up any interfaces or sockets.

Are you sure the trigger for this clearing of data happens during startup? Oddly I see that it successfully calculated a 24 hour dosage but the individual records are 0. There is no way it is summing this up to get a number other than 0.

[snagytx]

The 24h calculation doesn't seem to be related to the doseHistory - I can clear the history, restart njPC and the 24h calculation is still calculated - I didn't check the numbers if they are right or not.

I did another test - this time I pointed the dashboard to another njPC instance and pointed njPC to a bad host/port - to not receive messages

1. I restored the .json file and started njPC.
2. The doseHistory was restored from the data until 'http://localhost:4200/state/chemController/1/doseHistory' was called.
3. Executed the API call - the data was loaded and it was loaded incorrectly.
4. Stoped njPC.
5. Restored the json file
6. I changed the defaults for the "undefined" checks in the constructor like:

The response to the API was:

I'm 99% sure that this is the root cause, but I can't explain why - I guess the threading or something.

[snagytx]

I also backed out the changes in pull #359 just to be 100% sure it's not my changes - same behavior

[rstrouse]

Ok so I looked closer at this and the problem has to be that the incoming data is not being parsed on initial startup. Which is why it is hitting the default initializers. What I would like you to do is stop njsPC then restore your poolState.json with the correct values and restart njsPC. While it is starting up if it has some odd values we should see some obvious DataLogger error messages in the console.

So pull njsPC by going to the nodejs-poolController directory and type
git pull
npm i

Then restart njsPC and watch the console for messages related to the datalogger. I put a bunch of asterisks on these messages so they should be apparent.

[snagytx]

I pulled your changes and executed - nothing was logged.

To be 100% sure that I do what is required I added some extra code - I added the logs for successful parse:

I could see:

A DATALOGGER ENTRY WAS loaded string ************************************* {"id":1,"method":"auto","start":"2021-10-20T07:15:46.653-0500","end":"2021-10-20T07:18:31.569-0500","chem":"orp","setpoint":735,"demand":0,"level":692,"volume":0,"status":"completed","volumeDosed":181,"time":0,"timeDosed":83}

but in the ChemicalDoseState constructor the data is still not passed :(

[rstrouse]

ChemicalDoseState is a derived class of DataLoggerEntry. On line 417 or so you will see a line like

let o = extend(true, this, obj);

Add a console.log(this); right after that statement. Then lets see what it outputs.

Just to be sure what version of node are you running?

[snagytx]

I updated the code to:

I get:

The output of node -v gives:
v16.0.0

[snagytx]

I noticed the same issue on msmi/nodejs-poolcontroller - which uses v14.17.6

[snagytx]

This is from container:

Before docker-compose restart poolcontroller

After docker-compose restart poolcontroller

[rstrouse]

Well I'm not a docker user but I do know that node 16 hasn't even started active LTS support until the 26th and I am currently running 12 as 14 had serial port issues as well. Something may be up with the extend libraries and node still.

[snagytx]

I just used your Dockerfile, updated the base image from node:ltd-alpine to node:12-alpine, checked the output of node -v and it's v12.22.7 - tested the problem - the issue persists.

I'm 99% sure that you should reproduce the issue is you put my json file - if you need I can send you a more recent one.

[rstrouse]

But your after parse code shows that it parsed correctly. I guess I do not understand that it worked before you ran docker compose but after that it fails to parse. What is "this container". Honestly, I do not have a handle on docker but the most likely failure mode is that it failed to parse or the extend library failed to set the properties from the parsed object.

[rstrouse]

I copied your doseHistory into my poolState.json then shutdown and restarted a few times. No matter what I get the following.

Am I missing a step? The only difference is that I am not running in a docker container.

[rstrouse]

I tried it with the full poolConfig and State and still have success.

Hmmm... this is a bit of a mystery. If it parses properly then I am not sure what would clear it. When you shut down is the data in the poolState.jso still intact?

[snagytx]

The poolState.json is still valid if I start and stop the njsPC - but If I make the API call then exit - the bad data is getting saved. See attached

poolState-afterAPICall.txt

I don't have an explanation either, unless one of the dependent libraries is a different version - see attached the package-lock file

package-lock.txt

[rstrouse]

Which endpoint are you calling? There are several that probably need some work for IntelliChem. I assumed you were calling GET /state/chemController/1/doseHistory. Is that correct.

[snagytx]

You are correct, I'm using GET /state/chemController/1/doseHistory for testing. I'm not building/using a new client or something. I'm using the dashPanel - but I figured it's a simpler test case if you make the API call.

[rstrouse]

What is really interesting here is that dashPanel is calling that exact endpoint when you click on the 24 hour dose list. That being said there were some similar endpoints using a search verb on the api. I moved these from doseHistory to doseLog.

That being said I performed the exact steps. I replaced my doseHistory with yours called the api GET /state/chemController/1/doseHistory and got the expected results. I then restarted njsPC and called the api again. I got the expected results.

That being said I moved the other verbs around to see if there is something weird with the express routing. Pull njsPC and lets see if the other routes which are using TS templates were in the way.

If you want to try the route call GET /state/chemController/1/doseLog/ph. It may reveal some weirdness there that gives us an idea as to what is going on.

This will turn out to be something really simple.

[snagytx]

I pulled the new code and tested:
GET /state/chemController/1/doseLog/ph and GET /state/chemController/1/doseLog/orp provide the right/expected output
GET /state/chemController/1/doseHistory still gives the wrong output.

[rstrouse]

Just to be sure. Is this after you shut down njsPC then put the doseHistory back correctly into the poolState.json. Here are the steps I expected.

1. Shut down njsPC and update it
2. Start njsPC
3. Edit the poolState.json and put the correct values back into the doseHistory array.
4. call the GET /state/chemController/1/doseHistory --- Expect good results here
5. restart njsPC
6. call the GET /state/chemController/1/doseHistory --- Potentially bad results here

[snagytx]

I performed all the steps, step #4 failed - bad results here.

If you want you can reach out to me directly at snagytx81 On Gmail and we can setup a remote debug session - I'm a developer as well and I have all that I need to debug and update the code.

[rstrouse]

My availability is going to be very limited until the end of next week. However, in the meantime can I get you to make the edits to the poolState.json and then upload them here? When I get some time I will step it through the debugger.

[snagytx]

This is the poolState.txt file that I use. I just change the start and end dates to today. To make sure that they are in the last 24 yours.

poolState.txt

I'm available most of the day, CST, ping me and we can schedule a remote session when it's convenient to both of us.

[tagyoureit]

I can replicate this. I'll step through it tomorrow or over the weekend... should be easy for me to track down.

[tagyoureit]

I need @rstrouse's help to look at this. I see exactly where it is happened, but sitting here scratching my head. He may be out of town for the week... will get back with you soon.

[snagytx]

Exactly, I’m a developer for 15 years - other languages, and theoretically what I see makes no sense, super call to not pass this text to the extending class.

[tagyoureit]

I should have this fixed. Please check it out.

There were 2 issues at hand.

1. The string was being parsed back to an object with a reviver function (JSON.parse(entry, this.dateParser)). The last key/value of the reviver pair was '', {entire object} and causing parsing problems. (See this SO answer for more details.)

2. I moved the parsing of the entry from the base class (DataLoggerEntry) to the child class (ChemicalDoseState). I'm 99% sure this has to do with @rstrouse's comments:

 // Javascript is idiotic in that the initialization of variables
 // do not happen before the assignment so some of the values can be undefined.

[snagytx]

It seems that the changes you did resolved the problem. I'll keep an eye on the system.