tagyoureit / nodejs-poolController

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

Intellichlor showing "status not yet known" in web interface. #121

Closed stupid48 closed 5 years ago

stupid48 commented 5 years ago

Expected behavior and actual behavior

Intellichlor is controlled by Intellitouch Load Center Panel. Chlorinator is plugged into the panel and showing a good status. Panel is correctly reading status of chlorinator. PoolController web interface is showing "Status not yet known". When I query the rest interface, I get this: {"chlorinator":{"installed":0,"saltPPM":-1,"currentOutput":-1,"superChlorinate":-1,"version":-1,"name":"Intellichlor--40","controlledBy":"intellitouch"}}

Specifications

  1. What version of the code are you using? 5.3

Any idea what could be wrong?

tagyoureit commented 5 years ago

Yes, you just need to manually set it in your config.json file per this step.

stupid48 commented 5 years ago

I already have the setting "installed" set to 1 if that's what you mean.

I've attached my config.json

config.txt

tagyoureit commented 5 years ago

If you have installed: 1 in the config.json it should pick that up in the REST API responses. If not, restart the app. Also, your pool needs to be running or it will not provide power/messages from the chlorinator. That's sometimes another reason.

stupid48 commented 5 years ago

Hmm. I restarted and the pool is running. Diagnostics on the panel shows that the chlorinator is in a normal status. Not sure what else to check.

tagyoureit commented 5 years ago

If you want to attach a packet capture I can take a quick look.

stupid48 commented 5 years ago

I've attached the capture. It is a bunch of stops and starts in logging mode. Looking at the traffic, it seems that the UI only showed the chlorinator when it sent "Initial chlorinator settings discovered:" but that packet seems to be sent very sporadically (or it's getting lost). I do see other chlorinator packets more often though. The poolController was running this morning in normal node and I would have expected it to recognize the chlorinator when the pump started at 7AM?

capture.zip

tagyoureit commented 5 years ago

I see that you are getting the right results...

14:13:22.450 INFO Msg# 138   Initial chlorinator settings discovered:  {"controlledBy":"intellitouch","saltPPM":5000,"currentOutput":-1,"outputPoolPercent":45,"installed":1,"outputSpaPercent":3,"superChlorinate":0,"superChlorinateHours":0,"status":"Ok","name":"Intellichlor--40"}

The controller only sends this packet every ~30 seconds-1 minute. I see you only have 22 seconds captured in the logs. With your settings it will only show this message in the log once.

If you want to see more settings in the logs change these settings:

            "logLevel": "info", ==>             "logLevel": "silly",
            "logChlorinator": 0, ==>             "logChlorinator": 1,
stupid48 commented 5 years ago

So, I stopped it and started it with the new debug settings for about 20 minutes. When I look at the log, I do not see any packet saying "Initial chlorinator settings discovered". Strange...

stupid48 commented 5 years ago

After running all night and into the morning, I still haven't seen a packet that says "initial chlorinator settings discovered". I do see a bunch of these every minute or so:

15:55:49.454 SILLY iOAOA: Packet being analyzed: 0,4,77,77,0,0,82,87,0,0,3,0,0,120,131,3,13,3,209,16,2,80,17,45,160 **START OF NEW PACKET** 15:55:49.457 SILLY Aborting chlorinator packet because we reached the end of the buffer. 15:55:49.458 SILLY iOAOA: Criteria for recursing/exting. breakLoop: true

Is there something wrong with this packet that it is being aborted?

tagyoureit commented 5 years ago

I ran through your replay you sent me and (eventually) the chlorinator is discovered:

{
   "chlorinator": {
      "controlledBy": "intellitouch",
      "saltPPM": 5000,
      "currentOutput": -1,
      "outputPoolPercent": 45,
      "installed": 1,
      "outputSpaPercent": 3,
      "superChlorinate": 0,
      "superChlorinateHours": 0,
      "status": "Ok",
      "name": "Intellichlor--40"
   }
}

I really don't know why your controller isn't sending these packets more... maybe a loose wire???

As far as your previous question, those debug statements just mean we don't have an entire packet yet. The bytes received are still kept in the queue and eventually you will see they parse out correctly with something like:

19:55:06.451 SILLY pBTA: bufferToProcess length>0;  bufferArrayOfArrays>0.  CONCAT packetBuffer to BTP
19:55:06.451 SILLY iOAOA: Think we have a packet. bufferToProcess: 255,165,1,15,16,2,29,14,12,32,0,0,0,0,0,0,0,51,0,0,4,75,75,0,0,83,86,0,0,3,0,0,84,130,3,13,3,125  chatterlen: 37
19:55:06.451 DEBUG Msg# 309  Incoming controller packet: 165,1,15,16,2,29,14,12,32,0,0,0,0,0,0,0,51,0,0,4,75,75,0,0,83,86,0,0,3,0,0,84,130,3,13,3,125
19:55:06.452 SILLY Msg# 309   Making sure we have a valid controller packet (matching checksum to actual packet): [165,1,15,16,2,29,14,12,32,0,0,0,0,0,0,0,51,0,0,4,75,75,0,0,83,86,0,0,3,0,0,84,130,3,13,3,125]
19:55:06.452 SILLY Msg# 309   Match on Checksum:    893==893   165,1,15,16,2,29,14,12,32,0,0,0,0,0,0,0,51,0,0,4,75,75,0,0,83,86,0,0,3,0,0,84,130,3,13,3,125
19:55:06.453 SILLY Msg# 309  TYPE controller,  packet 165,1,15,16,2,29,14,12,32,0,0,0,0,0,0,0,51,0,0,4,75,75,0,0,83,86,0,0,3,0,0,84,130,3,13,3,125

I am a bit baffled here... not sure what is going on but the app seems ok once your controller sends the right packets.

stupid48 commented 5 years ago

Strange indeed. i guess I don't know what is going on. Appreciate your help though and thanks for your app!

tagyoureit commented 5 years ago

Closing for now. Reopen if you have new information to track down.