search

tagyoureit / nodejs-poolController

An application to control pool equipment from various manufacturers.
GNU Affero General Public License v3.0
315 stars 94 forks source link

[BUG] Possible issue with pump status message handling #800

Closed CodeSlinger69 closed 1 year ago

CodeSlinger69 commented 1 year ago

nodejs-poolController Version/commit

7.7.0 to 8.0.3

nodejs-poolController-dashPanel Version/commit

No response

relayEquipmentManager Version/commit

No response

Node Version

16.18.1

Platform

Linux poolvm 5.15.0-53-generic #59-Ubuntu SMP Mon Oct 17 18:53:30 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux

RS485 Adapter

Elfin EW11

Are you using Docker?

OCP

EasyTouch 4P

Pump(s)

No response

Chlorinator(s)

Intellichlor IC20

What steps will reproduce the bug?

As I was fiddling around today with my EW11, I had need to delete the data/poolConfig.json file to allow npc to redetect my equipment. Upon restart, I get this throw:

pool@poolvm:~/nodejs-poolController$ npm run start:cached

> nodejs-poolcontroller@7.7.0 start:cached
> node dist/app.js

Init state for Pool Controller
[6/23/2023, 7:07:55 PM] info: The current git branch output is master
[6/23/2023, 7:07:55 PM] info: The current git commit output is 8400e7f94940d068a1570d42a4a9a17b98f2e72a
[6/23/2023, 7:07:55 PM] info: Starting up SSDP server
[6/23/2023, 7:07:55 PM] info: Server is now listening on 0.0.0.0:4200
[6/23/2023, 7:07:58 PM] info: Net connect (socat) 0 connected to: 192.168.1.4:9801
[6/23/2023, 7:07:58 PM] info: Net connect (socat) Connection 0 connected
[6/23/2023, 7:07:58 PM] info: Net connect (socat) 0 ready and communicating: 192.168.1.4:9801
[6/23/2023, 7:07:58 PM] info: Checking njsPC versions...
[6/23/2023, 7:07:58 PM] info: Starting Pool System undefined
[6/23/2023, 7:07:58 PM] info: Listening for any installed OCPs
[6/23/2023, 7:07:58 PM] info: Auto-backup initialized Last Backup: 1969-12-31T17:00:00.000-0700
[6/23/2023, 7:07:58 PM] info: Found EasyTouch Controller
RESETTING DATA -- Controller type changed from undefined to easytouch
Pentair EasyTouch System Detected!
[6/23/2023, 7:07:58 PM] warn: dt:Fri Jun 23 2023 19:08:55 GMT-0700 (Mountain Standard Time) lat:undefined lon:undefined Not enough information to calculate Heliotrope.  See https://github.com/tagyoureit/nodejs-poolController/issues/245
[6/23/2023, 7:07:58 PM] warn: dt:Fri Jun 23 2023 19:08:55 GMT-0700 (Mountain Standard Time) lat:undefined lon:undefined Not enough information to calculate Heliotrope.  See https://github.com/tagyoureit/nodejs-poolController/issues/245
[6/23/2023, 7:07:58 PM] info: Requesting easytouch configuration
[6/23/2023, 7:07:59 PM] info: Checking njsPC versions...
[6/23/2023, 7:08:07 PM] warn: Message aborted after 4 attempt(s): 165,25,16,33,202,1,5,1,191 

/home/pool/nodejs-poolController/controller/comms/messages/Messages.ts:882
            throw new OutboundMessageError(out, `Invalid header detected: ${out.toShortPacket()}`);
                  ^
ApiError: Invalid header detected: 165,0,NaN,33,7,0,NaN,NaN
    at Function.create (/home/pool/nodejs-poolController/controller/comms/messages/Messages.ts:882:19)
    at Function.process (/home/pool/nodejs-poolController/controller/comms/messages/status/PumpStateMessage.ts:80:44)
    at Inbound.process (/home/pool/nodejs-poolController/controller/comms/messages/Messages.ts:734:38)
    at RS485Port.processCompletedMessage (/home/pool/nodejs-poolController/controller/comms/Comms.ts:803:17)
    at RS485Port.processInboundPackets (/home/pool/nodejs-poolController/controller/comms/Comms.ts:842:48)
    at RS485Port.processPackets (/home/pool/nodejs-poolController/controller/comms/Comms.ts:619:14)
    at Immediate._onImmediate (/home/pool/nodejs-poolController/controller/comms/Comms.ts:583:131)
    at processImmediate (node:internal/timers:466:21)

I noted in the throw that it had to do with the pump status message, so I edited the poolConfig.json file and replaced the empty pumps section with the pumps section from a known good version of the file:

  "pumps": [
    {
      "id": 1,
      "master": 0,
      "address": 96,
      "type": 128,
      "name": "Pump1",
      "flowStepSize": 1,
      "primingTime": 0,
      "primingSpeed": 450,
      "minSpeed": 450,
      "maxSpeed": 3450,
      "portId": 0,
      "isActive": true,
      "circuits": [
        {
          "circuit": 6,
          "speed": 1600,
          "units": 0,
          "master": 0,
          "id": 1
        },
        {
          "circuit": 3,
          "speed": 2600,
          "units": 0,
          "master": 0,
          "id": 2
        },
        {
          "circuit": 2,
          "speed": 2000,
          "units": 0,
          "master": 0,
          "id": 3
        }
      ],
      "minFlow": null,
      "maxFlow": null,
      "relays": []
    }
  ],

Upon restart, everything works fine. So it looks like its just related to the initial pump detection.

I also did a "git pull" and tested with the most current code. Same results.

Now if this is an issue that is very specific to my ancient EasyTouch 4P, then please don't bother. I have a workaround as shown above. But if this is a bug of more general applicability to the pump status message handling code, then please let me know if I can be of help to squash it.

Bonus information. There are some errors in stdout when starting with a new poolConfig.json, and after I manually add the pumps section, not sure if relevant, but thought I'd include here just in case. I can reproduce these with a "reload config":

[6/23/2023, 7:30:50 PM] warn: Message aborted after 4 attempt(s): 165,25,16,33,231,1,0,1,215 
[6/23/2023, 7:30:50 PM] error: Error sending configuration request message on port 0: Message aborted after 4 attempt(s): 165,25,16,33,231,1,0,1,215 ;
[6/23/2023, 7:30:56 PM] warn: Message aborted after 4 attempt(s): 165,25,16,33,216,1,1,1,201 
[6/23/2023, 7:30:56 PM] error: Error sending configuration request message on port 0: Message aborted after 4 attempt(s): 165,25,16,33,216,1,1,1,201 ;
[6/23/2023, 7:31:00 PM] warn: Message aborted after 4 attempt(s): 165,25,16,33,216,1,2,1,202 
[6/23/2023, 7:31:00 PM] error: Error sending configuration request message on port 0: Message aborted after 4 attempt(s): 165,25,16,33,216,1,2,1,202 ;

What happens?

Throw, hard crash.

What should have happened?

Pump message status should have been parsed.

Additional information

No response

rstrouse commented 1 year ago

Yeah the 4P does not respond to the pump configuration messages. Those are the 3 messages that were aborted and consequently these are the message responses that add the pump configuration to the pumps list. This absolutely is related to the old firmware on the 4P.

CodeSlinger69 commented 1 year ago

Great, thanks for confirming. Don't waste your time on it then, as my focus now is on cannibalizing the parts in that old OCP and building a Nixie. For the meantime, I have a workaround.