Manually setting Heat Mode crashes whole system

[StrikerS7R]

Kind of a wierd one that I've been working around for a while but want to get it resolved for this summer season. I have the system up and running fine with a SuperFlo VS, salt cell. 1 heater bypass valve and heat pump connected to Nixie. The schedules function (mostly) works well enabling the heater with a setpoint and pump speeds and whatnot but on hot days I've tried to turn on the heat pump earlier than the scheduled time.

Basically once I click the Heat Mode and set the Heat Pump as active, it works fine for ~10 seconds, fires the valve to route flow through the heater, fires the heater fireman relay to call for heat and runs long enough to start the heater then the whole Pi crashes and reboots back into the same cycle (now with the short cycle delay keeping the heater from actually turning on).

I've confirmed the Pi fully crashes as the VNC session disconnects and power lights on the Pi cycle. I can abort the cycle if I'm quick enough to set the Heat Mode to Off then it's back to stable and everything else works. It's quite odd.

I've run a couple logging captures to see if there's anything obvious (latest attached) and it actually looks like something is telling the system to shutdown but I can't tell what. It's even weirder that if the schedule works and enables the heater for a set point above current pool temp it turns on and runs fine.

I've tried using an independent relay to connect the heater (Raypak 8450ti) wires (44 & 46) using the Pi's Sequent Relay Hat in case it's something weird within the relay but no change there either. (Pi relay triggering another relay to connect the heater wires)

Further wierdness comes when I remove the relay entirely, I just connected the heater control wires together to always call for heat and relied on its flow switch to turn it on/off. Even disconnected Nixie from the REM to remove the Heater relay from the equation so it's just the heater valve going with the Any Heater Circuit to direct flow to the heater to turn it on. That still crashed the system somehow so I'm out of ideas and need help.

...
[02/05/2024, 12:24:50] info: {"port":0,"id":533,"valid":true,"dir":"out","proto":"chlorinator","pkt":[[],[], [16,2,80,0], [0],[98,16,3]],"ts":"2024-05-02T12:24:50.587-0700"}
[02/05/2024, 12:24:50] verbose: Wrote packet [Port 0 id: 533] [16,2,80,0,0,98,16,3].Retries remaining: 3 
[02/05/2024, 12:24:50] verbose: REM server request initiated. PUT /state/device/i2c:1:2:3 {"isOn":true,"latch":10000}
[02/05/2024, 12:24:50] silly: Message in 534 is a response for message out 533
[02/05/2024, 12:24:50] info: {"port":0,"id":534,"valid":true,"dir":"in","proto":"chlorinator","for":[533],"pkt":[[],[],[16,2,0,1],[0,0],[19,16,3]],"ts": "2024-05-02T12:24:50.643-0700"}
[02/05/2024, 12:24:50] verbose: REM server request returned. PUT /state/device/i2c:1:2:3 {"isOn":true,"latch":10000}
[02/05/2024, 12:24:50] debug: REM server request returned. PUT /state/device/i2c:1:2:3 {"isOn":true,"latch":10000} {"status":{"code":200,"message":"OK"},"data":"{\"id\":3,\"name\":\"MedHigh Speed\",\"enabled\":true,\"initState\":\"\",\"invert\":false,\"sequenceOnDelay\":200,\"sequenceOffDelay\":200,\"state\":true,\"tripTime\":1714677401780,\"oldState\":true,\"latchDuration\":488863}","obj":{"id":3,"name":"MedHigh Speed","enabled":true,"initState":"","invert":false,"sequenceOnDelay":200,"sequenceOffDelay":200,"state":true,"tripTime":1714677401780,"oldState":true,"latchDuration":488863}}
[02/05/2024, 12:24:50] verbose: REM server request initiated. PUT /state/device/i2c:1:2:7 {"isOn":true,"latch":10000}
[02/05/2024, 12:24:50] verbose: REM server request returned. PUT /state/device/i2c:1:2:7 {"isOn":true,"latch":10000}
[02/05/2024, 12:24:50] debug: REM server request returned. PUT /state/device/i2c:1:2:7 {"isOn":true,"latch":10000} {"status":{"code":200,"message":"OK"},"data":"{\"id\":7,\"name\":\"Heater Bypass\",\"enabled\":true,\"state\":true,\"initState\":\"\",\"invert\":false,\"sequenceOnDelay\":200,\"sequenceOffDelay\":200,\"tripTime\":1714677884598,\"oldState\":true,\"latchDuration\":6063}","obj":{"id":7,"name":"Heater Bypass","enabled":true,"state":true,"initState":"","invert":false,"sequenceOnDelay":200,"sequenceOffDelay":200,"tripTime":1714677884598,"oldState":true,"latchDuration":6063}}
[02/05/2024, 12:24:50] debug: Heater Type: heatpump Mode:heatpump Temp: 69.69 Setpoint: 78 Status: 4
[02/05/2024, 12:24:50] verbose: REM server request initiated. PUT /state/device/i2c:1:2:6 {"isOn":true,"latch":10000}
[02/05/2024, 12:24:50] verbose: REM server request returned. PUT /state/device/i2c:1:2:6 {"isOn":true,"latch":10000}
[02/05/2024, 12:24:50] debug: REM server request returned. PUT /state/device/i2c:1:2:6 {"isOn":true,"latch":10000} {"status":{"code":200,"message":"OK"},"data":"{\"id\":6,\"name\":\"Heater\",\"enabled\":true,\"state\":true,\"initState\":\"\",\"invert\":false,\"sequenceOnDelay\":200,\"sequenceOffDelay\":200,\"tripTime\":1714677884092,\"oldState\":true,\"latchDuration\":6590}","obj":{"id":6,"name":"Heater","enabled":true,"state":true,"initState":"","invert":false,"sequenceOnDelay":200,"sequenceOffDelay":200,"tripTime":1714677884092,"oldState":true,"latchDuration":6590}}
[02/05/2024, 12:24:50] info: {"port":0,"id":535,"valid":true,"dir":"out","proto":"chlorinator","pkt":[[],[], [16,2,80,17], [70],[185,16,3]],"ts":"2024-05-02T12:24:50.948-0700"}
[02/05/2024, 12:24:50] verbose: Wrote packet [Port 0 id: 535] [16,2,80,17,70,185,16,3].Retries remaining: 3 
[02/05/2024, 12:24:51] silly: Message in 536 is a response for message out 535
[02/05/2024, 12:24:51] info: {"port":0,"id":536,"valid":true,"dir":"in","proto":"chlorinator","for":[535],"pkt":[[],[],[16,2,0,18],[75,128],[239,16,3]],"ts": "2024-05-02T12:24:51.011-0700"}
[02/05/2024, 12:24:51] verbose: REM server request initiated. PUT /state/device/i2c:1:2:1 {"isOn":0}
[02/05/2024, 12:24:51] verbose: REM server request returned. PUT /state/device/i2c:1:2:1 {"isOn":0}
[02/05/2024, 12:24:51] debug: REM server request returned. PUT /state/device/i2c:1:2:1 {"isOn":0} {"status":{"code":200,"message":"OK"},"data":"{\"id\":1,\"name\":\"Low Speed\",\"enabled\":true,\"initState\":\"\",\"invert\":false,\"sequenceOnDelay\":200,\"sequenceOffDelay\":200,\"state\":false,\"tripTime\":1714498516019,\"oldState\":false,\"latchDuration\":179375419}","obj":{"id":1,"name":"Low Speed","enabled":true,"initState":"","invert":false,"sequenceOnDelay":200,"sequenceOffDelay":200,"state":false,"tripTime":1714498516019,"oldState":false,"latchDuration":179375419}}
[02/05/2024, 12:24:51] verbose: REM server request initiated. PUT /state/device/i2c:1:2:2 {"isOn":0}
[02/05/2024, 12:24:51] verbose: REM server request returned. PUT /state/device/i2c:1:2:2 {"isOn":0}
[02/05/2024, 12:24:51] debug: REM server request returned. PUT /state/device/i2c:1:2:2 {"isOn":0} {"status":{"code":200,"message":"OK"},"data":"{\"id\":2,\"name\":\"LowMed Speed\",\"enabled\":true,\"initState\":\"\",\"invert\":false,\"sequenceOnDelay\":200,\"sequenceOffDelay\":200,\"state\":false,\"tripTime\":1714676461645,\"oldState\":false,\"latchDuration\":1429808}","obj":{"id":2,"name":"LowMed Speed","enabled":true,"initState":"","invert":false,"sequenceOnDelay":200,"sequenceOffDelay":200,"state":false,"tripTime":1714676461645,"oldState":false,"latchDuration":1429808}}
[02/05/2024, 12:24:51] verbose: REM server request initiated. PUT /state/device/i2c:1:2:3 {"isOn":1,"latch":5000}
[02/05/2024, 12:24:51] verbose: REM server request returned. PUT /state/device/i2c:1:2:3 {"isOn":1,"latch":5000}
[02/05/2024, 12:24:51] debug: REM server request returned. PUT /state/device/i2c:1:2:3 {"isOn":1,"latch":5000} {"status":{"code":200,"message":"OK"},"data":"{\"id\":3,\"name\":\"MedHigh Speed\",\"enabled\":true,\"initState\":\"\",\"invert\":false,\"sequenceOnDelay\":200,\"sequenceOffDelay\":200,\"state\":true,\"tripTime\":1714677401780,\"oldState\":true,\"latchDuration\":489687}","obj":{"id":3,"name":"MedHigh Speed","enabled":true,"initState":"","invert":false,"sequenceOnDelay":200,"sequenceOffDelay":200,"state":true,"tripTime":1714677401780,"oldState":true,"latchDuration":489687}}
[02/05/2024, 12:24:51] verbose: REM server request initiated. PUT /state/device/i2c:1:2:4 {"isOn":1,"latch":5000}
[02/05/2024, 12:24:51] verbose: REM server request returned. PUT /state/device/i2c:1:2:4 {"isOn":1,"latch":5000}
[02/05/2024, 12:24:51] debug: REM server request returned. PUT /state/device/i2c:1:2:4 {"isOn":1,"latch":5000} {"status":{"code":200,"message":"OK"},"data":"{\"id\":4,\"name\":\"High Speed\",\"enabled\":true,\"initState\":\"\",\"invert\":false,\"sequenceOnDelay\":200,\"sequenceOffDelay\":200,\"state\":true,\"tripTime\":1714677885356,\"oldState\":true,\"latchDuration\":6125}","obj":{"id":4,"name":"High Speed","enabled":true,"initState":"","invert":false,"sequenceOnDelay":200,"sequenceOffDelay":200,"state":true,"tripTime":1714677885356,"oldState":true,"latchDuration":6125}}
[02/05/2024, 12:24:52] debug: Heater Type: heatpump Mode:heatpump Temp: 69.69 Setpoint: 78 Status: 4
[02/05/2024, 12:24:52] verbose: REM server request initiated. PUT /state/device/i2c:1:2:6 {"isOn":true,"latch":10000}
[02/05/2024, 12:24:52] debug: Heater Type: heatpump Mode:heatpump Temp: 69.69 Setpoint: 78 Status: 4
[02/05/2024, 12:24:52] verbose: REM server request initiated. PUT /state/device/i2c:1:2:6 {"isOn":true,"latch":10000}
[02/05/2024, 12:24:52] verbose: REM server request returned. PUT /state/device/i2c:1:2:6 {"isOn":true,"latch":10000}
[02/05/2024, 12:24:52] debug: REM server request returned. PUT /state/device/i2c:1:2:6 {"isOn":true,"latch":10000} {"status":{"code":200,"message":"OK"},"data":"{\"id\":6,\"name\":\"Heater\",\"enabled\":true,\"state\":true,\"initState\":\"\",\"invert\":false,\"sequenceOnDelay\":200,\"sequenceOffDelay\":200,\"tripTime\":1714677884092,\"oldState\":true,\"latchDuration\":8134}","obj":{"id":6,"name":"Heater","enabled":true,"state":true,"initState":"","invert":false,"sequenceOnDelay":200,"sequenceOffDelay":200,"tripTime":1714677884092,"oldState":true,"latchDuration":8134}}
[02/05/2024, 12:24:52] verbose: REM server request returned. PUT /state/device/i2c:1:2:6 {"isOn":true,"latch":10000}
[02/05/2024, 12:24:52] debug: REM server request returned. PUT /state/device/i2c:1:2:6 {"isOn":true,"latch":10000} {"status":{"code":200,"message":"OK"},"data":"{\"id\":6,\"name\":\"Heater\",\"enabled\":true,\"state\":true,\"initState\":\"\",\"invert\":false,\"sequenceOnDelay\":200,\"sequenceOffDelay\":200,\"tripTime\":1714677884092,\"oldState\":true,\"latchDuration\":8147}","obj":{"id":6,"name":"Heater","enabled":true,"state":true,"initState":"","invert":false,"sequenceOnDelay":200,"sequenceOffDelay":200,"tripTime":1714677884092,"oldState":true,"latchDuration":8147}}
[02/05/2024, 12:24:53] info: Shut down sys (config) object timers
[02/05/2024, 12:24:53] info: Nixie: Set Heatpump 256-Heat Pump to false
[02/05/2024, 12:24:53] verbose: REM server request initiated. PUT /state/device/i2c:1:2:6 {"isOn":false}
[02/05/2024, 12:24:53] info: NCP: Setting Pump SuperFlo VS relays to Relay 1: off, Relay 2: off, Relay 3: off, and Relay 4: on.
[02/05/2024, 12:24:53] verbose: REM server request initiated. PUT /state/device/i2c:1:2:1 {"isOn":0}
[02/05/2024, 12:24:53] verbose: REM server request returned. PUT /state/device/i2c:1:2:6 {"isOn":false}
[02/05/2024, 12:24:53] debug: REM server request returned. PUT /state/device/i2c:1:2:6 {"isOn":false} {"status":{"code":500,"message":"Internal Server Error"},"error":{"stack":"Error: setDeviceState: Error setting device state Cannot read properties of undefined (reading 'setDeviceState')\n    at I2cDevice.setDeviceState (/home/pi/relayEquipmentManager/boards/Controller.ts:3010:45)\n    at I2cBus.setDeviceState (/home/pi/relayEquipmentManager/boards/Controller.ts:2417:33)\n    at I2cController.setDeviceState (/home/pi/relayEquipmentManager/boards/Controller.ts:2027:30)\n    at Controller.setDeviceState (/home/pi/relayEquipmentManager/boards/Controller.ts:589:39)\n    at /home/pi/relayEquipmentManager/web/services/State.ts:86:38\n    at Layer.handle [as handle_request] (/home/pi/relayEquipmentManager/node_modules/express/lib/router/layer.js:95:5)\n    at next (/home/pi/relayEquipmentManager/node_modules/express/lib/router/route.js:144:13)\n    at Route.dispatch (/home/pi/relayEquipmentManager/node_modules/express/lib/router/route.js:114:3)\n    at Layer.handle [as handle_request] (/home/pi/relayEquipmentManager/node_modules/express/lib/router/layer.js:95:5)\n    at /home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:284:15\n    at param (/home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:365:14)\n    at param (/home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:376:14)\n    at Function.process_params (/home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:421:3)\n    at next (/home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:280:10)\n    at /home/pi/relayEquipmentManager/web/Server.ts:281:17\n    at Layer.handle [as handle_request] (/home/pi/relayEquipmentManager/node_modules/express/lib/router/layer.js:95:5)","message":"setDeviceState: Error setting device state Cannot read properties of undefined (reading 'setDeviceState')","level":"\u001b[31merror\u001b[39m","timestamp":"02/05/2024, 12:24:53"},"data":""}
[02/05/2024, 12:24:53] error: Nixie Error setting heatpump state: 500 -Internal Server Error setDeviceState: Error setting device state Cannot read properties of undefined (reading 'setDeviceState')
[02/05/2024, 12:24:53] verbose: REM server request initiated. PUT /state/device/i2c:1:2:8 {"isOn":false}
[02/05/2024, 12:24:53] verbose: REM server request returned. PUT /state/device/i2c:1:2:1 {"isOn":0}
[02/05/2024, 12:24:53] debug: REM server request returned. PUT /state/device/i2c:1:2:1 {"isOn":0} {"status":{"code":500,"message":"Internal Server Error"},"error":{"stack":"Error: setDeviceState: Error setting device state Cannot read properties of undefined (reading 'setDeviceState')\n    at I2cDevice.setDeviceState (/home/pi/relayEquipmentManager/boards/Controller.ts:3010:45)\n    at I2cBus.setDeviceState (/home/pi/relayEquipmentManager/boards/Controller.ts:2417:33)\n    at I2cController.setDeviceState (/home/pi/relayEquipmentManager/boards/Controller.ts:2027:30)\n    at Controller.setDeviceState (/home/pi/relayEquipmentManager/boards/Controller.ts:589:39)\n    at /home/pi/relayEquipmentManager/web/services/State.ts:86:38\n    at Layer.handle [as handle_request] (/home/pi/relayEquipmentManager/node_modules/express/lib/router/layer.js:95:5)\n    at next (/home/pi/relayEquipmentManager/node_modules/express/lib/router/route.js:144:13)\n    at Route.dispatch (/home/pi/relayEquipmentManager/node_modules/express/lib/router/route.js:114:3)\n    at Layer.handle [as handle_request] (/home/pi/relayEquipmentManager/node_modules/express/lib/router/layer.js:95:5)\n    at /home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:284:15\n    at param (/home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:365:14)\n    at param (/home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:376:14)\n    at Function.process_params (/home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:421:3)\n    at next (/home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:280:10)\n    at /home/pi/relayEquipmentManager/web/Server.ts:281:17\n    at Layer.handle [as handle_request] (/home/pi/relayEquipmentManager/node_modules/express/lib/router/layer.js:95:5)","message":"setDeviceState: Error setting device state Cannot read properties of undefined (reading 'setDeviceState')","level":"\u001b[31merror\u001b[39m","timestamp":"02/05/2024, 12:24:53"},"data":""}
[02/05/2024, 12:24:53] verbose: REM server request initiated. PUT /state/device/i2c:1:2:2 {"isOn":0}
[02/05/2024, 12:24:53] verbose: REM server request returned. PUT /state/device/i2c:1:2:8 {"isOn":false}
[02/05/2024, 12:24:53] debug: REM server request returned. PUT /state/device/i2c:1:2:8 {"isOn":false} {"status":{"code":500,"message":"Internal Server Error"},"error":{"stack":"Error: setDeviceState: Error setting device state Cannot read properties of undefined (reading 'setDeviceState')\n    at I2cDevice.setDeviceState (/home/pi/relayEquipmentManager/boards/Controller.ts:3010:45)\n    at I2cBus.setDeviceState (/home/pi/relayEquipmentManager/boards/Controller.ts:2417:33)\n    at I2cController.setDeviceState (/home/pi/relayEquipmentManager/boards/Controller.ts:2027:30)\n    at Controller.setDeviceState (/home/pi/relayEquipmentManager/boards/Controller.ts:589:39)\n    at /home/pi/relayEquipmentManager/web/services/State.ts:86:38\n    at Layer.handle [as handle_request] (/home/pi/relayEquipmentManager/node_modules/express/lib/router/layer.js:95:5)\n    at next (/home/pi/relayEquipmentManager/node_modules/express/lib/router/route.js:144:13)\n    at Route.dispatch (/home/pi/relayEquipmentManager/node_modules/express/lib/router/route.js:114:3)\n    at Layer.handle [as handle_request] (/home/pi/relayEquipmentManager/node_modules/express/lib/router/layer.js:95:5)\n    at /home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:284:15\n    at param (/home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:365:14)\n    at param (/home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:376:14)\n    at Function.process_params (/home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:421:3)\n    at next (/home/pi/relayEquipmentManager/node_modules/express/lib/router/index.js:280:10)\n    at /home/pi/relayEquipmentManager/web/Server.ts:281:17\n    at Layer.handle [as handle_request] (/home/pi/relayEquipmentManager/node_modules/express/lib/router/layer.js:95:5)","message":"setDeviceState: Error setting device state Cannot read properties of undefined (reading 'setDeviceState')","level":"\u001b[31merror\u001b[39m","timestamp":"02/05/2024, 12:24:53"},"data":""}
[02/05/2024, 12:24:53] verbose: REM server request initiated. PUT /state/device/i2c:1:2:5 {"isOn":false}
[02/05/2024, 12:24:53] error: Error sending Request: PUT /state/device/i2c:1:2:2 read ECONNRESET
[2024-05-02_12-16-36.zip](https://github.com/tagyoureit/nodejs-poolController/files/15193526/2024-05-02_12-16-36.zip)

...

2024-05-02_12-16-36.zip

[tagyoureit]

Please do the following.

1. Turn on logging in REM.

2. Run the same packet capture again in njsPC.
3. Send the njsPC output and also the files from the REM directories /data and /logs.
4. Turn logging back off.

I see errors in the njsPC logs and want to track them down in REM. This also reminds me I want to include REM log files with njsPC captures!

[StrikerS7R]

Sure thing, I put the Heater relay REM connection back in before this capture so it's in the normal state. REM /data and /logs as well as njsPC zip attached here.
2024.5.3-HeaterCrashLog.zip

[tagyoureit]

Pull both REM and njsPC. I had a fix in njsPC a few weeks ago that should limit the number of calls between both apps. And I just put in a check for an undefined device that incorrectly looking for an undefined bus. If this doesn't fix it, I'll look further into why it isn't finding the device, but the worst case is it should fail more gracefully now.

[StrikerS7R]

Thanks @tagyoureit, pulled the latest for both and restarted.

I think I may have found the source yesterday before seeing your update here. It was my doing (unsurprisingly) and looking at the logs you requested refreshed a memory. Seemed odd that both REM and njsPC were both getting a clean shutdown request without anything obvious (to me anyway) triggering it. I remembered that when I first got this Pi4 and was learning a bit about it and getting it set up for this purpose I had installed the attached script in order to have the physical button on the Pi do a safe restart/shutdown since it was going to be located out on my pool pad and I didn't have reliable wifi out there yet. Totally random thought but could be related and it was really low stakes to remove it since njsPC has been so stable outside this issue. I pulled it out of /etc/rc.local and rebooted and after a couple attempts to recreate the Heater mode crash I can't get it to reoccur.

Super random but think somehow the heater mode setting in njsPC was triggering that script to reboot the Pi.

safe_restart_shutdown_interrupt_Pi.py.zip

[tagyoureit]

That totally makes sense. I don't immediately see anything in REM tied to GPIO 26, but the timing certainly is right. Good find.