OpenTherm monitor stuck in PS=1 mode

[ebaauw]

During initialisation, homebridge-otgw issues a PS=1 command, to request a summary from the OpenTherm Monitor. This also causes the monitor to stop logging OpenTherm messages. Normally, homebridge-otgw should issue a PS=0 to resume logging, but on occasion it doesn't (or maybe the message is lost?).

As a safeguard homebridge-otgw should issue PS=0 either periodically, or check whether it's still receiving regular messages.

[ebaauw]

Seems to be a timing issue:

Nov 12 20:30:24 pi2 homebridge[22959]: [OTGW] send command: PS=1
Nov 12 20:30:25 pi2 homebridge[22959]: [OTGW] command: PS=1
Nov 12 20:30:29 pi2 homebridge[22959]: [OTGW] send command: PS=1 [1]
Nov 12 20:30:29 pi2 homebridge[22959]: [OTGW] send command: PS=1
Nov 12 20:30:29 pi2 homebridge[22959]: [OTGW] command: PS=1
Nov 12 20:30:29 pi2 homebridge[22959]: [OTGW] send command: PS=1, response: 1
Nov 12 20:30:29 pi2 homebridge[22959]: [OTGW] command: PS=1
Nov 12 20:30:29 pi2 homebridge[22959]: [OTGW] summary: {"master_status_ch_enable":false,"master_status_dhw_enable":true,"slave_status_fault":false,"slave_status_ch_mode":false,"slave_status_dhw_mode":false,"slave_status_flame_status":false,"slave_status_diagnostic_indication":false,"control_setpoint":10,"remote_parameter_enable_dwh_setpoint":true,"remote_parameter_enable_max_ch_setpoint":true,"remote_parameter_write_dwh_setpoint":true,"remote_parameter_write_max_ch_setpoint":true,"max_reletive_modulation_setting":0,"max_boiler_capacity":0,"min_modulation_level":0,"room_setpoint":21,"relative_modulation_level":0,"ch_water_pressure":0,"room_temperature":21.48,"boiler_water_temperature":44.21,"dhw_temperature":0,"outside_temperature":5.33,"return_water_temperature":44,"dhw_setpoint_max":65,"dhw_setpoint_min":40,"max_ch_setpoint_max":85,"max_ch_setpoint_min":20,"dhw_setpoint":65,"max_ch_setpoint":85,"burner_starts":6904,"ch_pump_starts":6752,"dhw_pump_starts":3336,"dhw_burner_starts":4000,"burner_operation_hours":448,"ch_pump_operation_hours":560,"dhw_pump_operation_hours":4784,"dhw_burner_operation_hours":112}
Nov 12 20:30:29 pi2 homebridge[22959]: [OTGW] send command: PS=0
Nov 12 20:30:29 pi2 homebridge[22959]: [OTGW] command: PS=0
Nov 12 20:30:29 pi2 homebridge[22959]: [OTGW] send command: PS=0, response: 0
Nov 12 20:30:30 pi2 homebridge[22959]: [OTGW] send command: PS=1 [1]
Nov 12 20:30:30 pi2 homebridge[22959]: [OTGW] command: PS=1
Nov 12 20:30:33 pi2 homebridge[22959]: [OTGW] send command: PS=1 [2]
Nov 12 20:30:33 pi2 homebridge[22959]: [OTGW] command: PS=1
Nov 12 20:30:33 pi2 homebridge[22959]: [OTGW] send command: PS=1, response: 1

[ebaauw]

Damn. I though I found the cause, but after installing v0.0.31 on my production Pi, the issue occurred right away. Had to issue PS=1 from the OpenTerm Monitor to start homebridge-otgw.

Funny, the monitor shows the summary (at 15:58:44):

But it's not received by homebridge-otgw?

Feb 21 15:58:42 pi2 homebridge[8205]: [OTGW] B40000200: {"master_status_ch_enable":false,"master_status_dhw_enable":true,"slave_status_fault":false,"slave_status_ch_mode":false,"slave_status_dhw_mode":false,"slave_status_flame_status":false,"slave_status_diagnostic_indication":false}
Feb 21 15:58:42 pi2 homebridge[8205]: [Weather] Amsterdam History: add entry 30826: {"time":1582297122,"temp":8.9,"humidity":70,"pressure":1022}
Feb 21 15:58:42 pi2 homebridge[8205]: [Weather] Amsterdam History: set history status to: c7011901 00000000 db25e722 [03 0102 0202 0302] c00f c00f ab680000 000000000101
Feb 21 15:58:42 pi2 homebridge[8205]: [Weather] Amsterdam History: set History Status from "wP8YAQAAAADbJeciAwECAgIDAsAPwA+paAAAAAAAAAEB" to "xwEZAQAAAADbJeciAwECAgIDAsAPwA+raAAAAAAAAAEB"
Feb 21 15:58:42 pi2 homebridge[8205]: [OTGW] BD0010A00: {"control_setpoint":10}
Feb 21 15:58:43 pi2 homebridge[8205]: [OTGW] send command: PS=1 [1]
Feb 21 15:58:43 pi2 homebridge[8205]: [OTGW] B40000200: {"master_status_ch_enable":false,"master_status_dhw_enable":true,"slave_status_fault":false,"slave_status_ch_mode":false,"slave_status_dhw_mode":false,"slave_status_flame_status":false,"slave_status_diagnostic_indication":false}
Feb 21 15:58:43 pi2 homebridge[8205]: [OTGW] B40192466: {"boiler_water_temperature":36.4}
Feb 21 15:58:43 pi2 homebridge[8205]: [OTGW] command: PS=1
Feb 21 15:58:43 pi2 homebridge[8205]: [Sonos] RINCON_347E5C318CBE01400 [Katja]: request 9: status 200 OK
Feb 21 15:58:44 pi2 homebridge[8205]: [OTGW] response: PS: 1
Feb 21 15:58:44 pi2 homebridge[8205]: [OTGW] send command: PS=1, response: 1
Feb 21 15:58:44 pi2 homebridge[8205]: [Sonos] RINCON_5CAAFD9EAF0A01400 [Bedroom (L)]: request 9: status 200 OK
Feb 21 15:58:44 pi2 homebridge[8205]: [Sonos] RINCON_949F3E0E142C01400 [Bathroom]: request 9: status 200 OK
Feb 21 15:58:44 pi2 homebridge[8205]: [Sonos] RINCON_000E58A8171201400 [Home]: request 9: status 200 OK
Feb 21 15:58:45 pi2 homebridge[8205]: [Lib] warning: heartbeat 7, drift 846
Feb 21 15:58:45 pi2 homebridge[8205]: [Config] Homebridge Config UI X v4.10.3 is listening on :: port 8081
Feb 21 15:58:46 pi2 homebridge[8205]: [Lib] warning: heartbeat 8, drift 331
Feb 21 15:58:46 pi2 homebridge[8205]: [Lib] warning: heartbeat 9, drift 301
Feb 21 15:58:48 pi2 homebridge[8205]: [Lib] warning: heartbeat 10, drift 442
Feb 21 15:58:48 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption from 8729.539 kWh to 8729.541 kWh
Feb 21 15:58:48 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption normal from 3375.42 kWh to 3375.422 kWh
Feb 21 15:58:48 pi2 homebridge[8205]: [P1] Electricity: set homekit current consumption from 482 W to 465 W
Feb 21 15:58:50 pi2 homebridge[8205]: [Lib] warning: heartbeat 12, drift 339
Feb 21 15:58:56 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption from 8729.541 kWh to 8729.542 kWh
Feb 21 15:58:56 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption normal from 3375.422 kWh to 3375.423 kWh
Feb 21 15:58:56 pi2 homebridge[8205]: [P1] Electricity: set homekit current consumption from 465 W to 448 W
Feb 21 15:59:00 pi2 homebridge[8205]: [OTGW] command: SC=15:59/5
Feb 21 15:59:00 pi2 homebridge[8205]: [OTGW] response: SC: 15:59/5
Feb 21 15:59:06 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption from 8729.542 kWh to 8729.543 kWh
Feb 21 15:59:06 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption normal from 3375.423 kWh to 3375.424 kWh
Feb 21 15:59:06 pi2 homebridge[8205]: [P1] Electricity: set homekit current consumption from 448 W to 409 W
Feb 21 15:59:07 pi2 homebridge[8205]: [Lib] flush cachedAccessories
Feb 21 15:59:07 pi2 homebridge[8205]: [Sonos] RINCON_949F3E0E142C01400 [Bathroom]: lastSeen: 23s ago at 192.168.76.77, bootSeq: 66
Feb 21 15:59:07 pi2 homebridge[8205]: [Sonos] RINCON_5CAAFD9EAF0A01400 [Bedroom (L)]: lastSeen: 23s ago at 192.168.76.78, bootSeq: 115
Feb 21 15:59:07 pi2 homebridge[8205]: [Sonos] RINCON_5CAAFD9EAFD401400 [Bedroom (R)]: lastSeen: 29s ago at 192.168.76.79, bootSeq: 96
Feb 21 15:59:07 pi2 homebridge[8205]: [Sonos] RINCON_B8E937DF892C01400 [Dining Room (L)]: lastSeen: 25s ago at 192.168.76.75, bootSeq: 95
Feb 21 15:59:07 pi2 homebridge[8205]: [Sonos] RINCON_B8E937DFD0A201400 [Dining Room (R)]: lastSeen: 28s ago at 192.168.76.76, bootSeq: 104
Feb 21 15:59:07 pi2 homebridge[8205]: [Sonos] RINCON_000E58A8171201400 [Home]: lastSeen: 23s ago at 192.168.76.70, bootSeq: 322
Feb 21 15:59:07 pi2 homebridge[8205]: [Sonos] RINCON_347E5C318CBE01400 [Katja]: lastSeen: 24s ago at 192.168.76.90, bootSeq: 187
Feb 21 15:59:07 pi2 homebridge[8205]: [Sonos] RINCON_5CAAFD1FA0D701400 [Living Room]: lastSeen: 26s ago at 192.168.76.71, bootSeq: 148
Feb 21 15:59:07 pi2 homebridge[8205]: [Sonos] RINCON_5CAAFD7C941401400 [Living Room (LS)]: lastSeen: 29s ago at 192.168.76.72, bootSeq: 172
Feb 21 15:59:07 pi2 homebridge[8205]: [Sonos] RINCON_5CAAFD7C940401400 [Living Room (RS)]: lastSeen: 29s ago at 192.168.76.73, bootSeq: 139
Feb 21 15:59:07 pi2 homebridge[8205]: [Sonos] RINCON_949F3EAECB4801400 [Living Room (Sub)]: lastSeen: 29s ago at 192.168.76.74, bootSeq: 10
Feb 21 15:59:16 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption from 8729.543 kWh to 8729.544 kWh
Feb 21 15:59:16 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption normal from 3375.424 kWh to 3375.425 kWh
Feb 21 15:59:16 pi2 homebridge[8205]: [P1] Electricity: set homekit current consumption from 409 W to 407 W
Feb 21 15:59:26 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption from 8729.544 kWh to 8729.546 kWh
Feb 21 15:59:26 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption normal from 3375.425 kWh to 3375.427 kWh
Feb 21 15:59:26 pi2 homebridge[8205]: [P1] Electricity: set homekit current consumption from 407 W to 416 W
Feb 21 15:59:36 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption from 8729.546 kWh to 8729.547 kWh
Feb 21 15:59:36 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption normal from 3375.427 kWh to 3375.428 kWh
Feb 21 15:59:36 pi2 homebridge[8205]: [P1] Electricity: set homekit current consumption from 416 W to 407 W
Feb 21 15:59:46 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption from 8729.547 kWh to 8729.548 kWh
Feb 21 15:59:46 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption normal from 3375.428 kWh to 3375.429 kWh
Feb 21 15:59:46 pi2 homebridge[8205]: [P1] Electricity: set homekit current consumption from 407 W to 409 W
Feb 21 15:59:52 pi2 homebridge[8205]: [OTGW] command: PR=M
Feb 21 15:59:53 pi2 homebridge[8205]: [OTGW] response: PR: M=G
Feb 21 15:59:56 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption from 8729.548 kWh to 8729.549 kWh
Feb 21 15:59:56 pi2 homebridge[8205]: [P1] Electricity: set homekit total consumption normal from 3375.429 kWh to 3375.43 kWh
Feb 21 15:59:56 pi2 homebridge[8205]: [P1] Electricity: set homekit current consumption from 409 W to 413 W
Feb 21 15:59:58 pi2 homebridge[8205]: [OTGW] command: PS=1
Feb 21 15:59:58 pi2 homebridge[8205]: [OTGW] response: PS: 1
Feb 21 15:59:58 pi2 homebridge[8205]: [OTGW] summary: {"master_status_ch_enable":false,"master_status_dhw_enable":true,"slave_status_fault":false,"slave_status_ch_mode":false,"slave_status_dhw_mode":false,"slave_status_flame_status":false,"slave_status_diagnostic_indication":false,"control_setpoint":10,"remote_parameter_enable_dwh_setpoint":true,"remote_parameter_enable_max_ch_setpoint":true,"remote_parameter_write_dwh_setpoint":true,"remote_parameter_write_max_ch_setpoint":true,"max_relative_modulation_setting":0,"max_boiler_capacity":0,"min_modulation_level":0,"room_setpoint":21,"relative_modulation_level":0,"ch_water_pressure":0,"room_temperature":21.26,"boiler_water_temperature":36.1,"dhw_temperature":0,"outside_temperature":8.91,"return_water_temperature":35.7,"dhw_setpoint_max":65,"dhw_setpoint_min":40,"max_ch_setpoint_max":85,"max_ch_setpoint_min":20,"dhw_setpoint":65,"max_ch_setpoint":85,"burner_starts":12336,"ch_pump_starts":11872,"dhw_pump_starts":8080,"dhw_burner_starts":5088,"burner_operation_hours":1368,"ch_pump_operation_hours":1592,"dhw_pump_operation_hours":6216,"dhw_burner_operation_hours":152}
Feb 21 15:59:58 pi2 homebridge[8205]: [OTGW] send command: PS=0
Feb 21 15:59:58 pi2 homebridge[8205]: [OTGW] command: PS=0
Feb 21 15:59:58 pi2 homebridge[8205]: [OTGW] response: PS: 0
Feb 21 15:59:58 pi2 homebridge[8205]: [OTGW] send command: PS=0, response: 0
Feb 21 15:59:58 pi2 homebridge[8205]: [OTGW] Thermostat: set Current Temperature from 21.5°C to 21.3°C
Feb 21 15:59:58 pi2 homebridge[8205]: [OTGW] Boiler: set Current Temperature from 36.4°C to 36.1°C
Feb 21 15:59:58 pi2 homebridge[8205]: [OTGW] HotWater: set Current Temperature from 36.4°C to 36.1°C
Feb 21 15:59:58 pi2 homebridge[8205]: [OTGW] initialised
Feb 21 15:59:58 pi2 homebridge[8205]: [OTGW] BC0790638: {"ch_pump_operation_hours":1592}
Feb 21 15:59:58 pi2 homebridge[8205]: [OTGW] AC01B08E9: {"outside_temperature":8.91}
Feb 21 15:59:59 pi2 homebridge[8205]: [OTGW] BC0192419: {"boiler_water_temperature":36.1}
Feb 21 15:59:59 pi2 homebridge[8205]: [OTGW] B40000200: {"master_status_ch_enable":false,"master_status_dhw_enable":true,"slave_status_fault":false,"slave_status_ch_mode":false,"slave_status_dhw_mode":false,"slave_status_flame_status":false,"slave_status_diagnostic_indication":false}
Feb 21 16:00:00 pi2 homebridge[8205]: [OTGW] command: SC=16:00/5
Feb 21 16:00:00 pi2 homebridge[8205]: [OTGW] response: SC: 16:00/5
Feb 21 16:00:00 pi2 homebridge[8205]: [OTGW] B40000200: {"master_status_ch_enable":false,"master_status_dhw_enable":true,"slave_status_fault":false,"slave_status_ch_mode":false,"slave_status_dhw_mode":false,"slave_status_flame_status":false,"slave_status_diagnostic_indication":false}
Feb 21 16:00:00 pi2 homebridge[8205]: [OTGW] B40000200: {"master_status_ch_enable":false,"master_status_dhw_enable":true,"slave_status_fault":false,"slave_status_ch_mode":false,"slave_status_dhw_mode":false,"slave_status_flame_status":false,"slave_status_diagnostic_indication":false}

I'm running multiple plugins in the same homebridge instance, and do see some drift. But I find it hard to believe that NodeJS would somehow miss websocket data.

[ebaauw]

Oh the joy of asynchronous programming...

But I find it hard to believe that NodeJS would somehow miss websocket data.

I issued the summary log message from the (on-time) event handler, instead of from the parser. The message is received alright, but not logged. After changing that and a couple of homebridge restarts... Bingo!:

Feb 21 16:40:16 pi2 homebridge[7545]: [OTGW] message: Command (via websocket from 127.0.0.1:36664): PS=1
Feb 21 16:40:16 pi2 homebridge[7545]: [OTGW] message: PS: 1
Feb 21 16:40:16 pi2 homebridge[7545]: [Lib] warning: heartbeat 8, drift 528
Feb 21 16:40:16 pi2 homebridge[7545]: [OTGW] message: 00000010/00000000,10.00,00000011/00000011,0.00,0/0,21.00,0.00,0.00,21.41,36.10,0.00,8.83,35.70,65/40,85/20,65.00,85.00,12344,11872,8080,5088,1368,1592,6216,152
Feb 21 16:40:16 pi2 homebridge[7545]: [OTGW] summary: {"master_status_ch_enable":false,"master_status_dhw_enable":true,"slave_status_fault":false,"slave_status_ch_mode":false,"slave_status_dhw_mode":false,"slave_status_flame_status":false,"slave_status_diagnostic_indication":false,"control_setpoint":10,"remote_parameter_enable_dwh_setpoint":true,"remote_parameter_enable_max_ch_setpoint":true,"remote_parameter_write_dwh_setpoint":true,"remote_parameter_write_max_ch_setpoint":true,"max_relative_modulation_setting":0,"max_boiler_capacity":0,"min_modulation_level":0,"room_setpoint":21,"relative_modulation_level":0,"ch_water_pressure":0,"room_temperature":21.41,"boiler_water_temperature":36.1,"dhw_temperature":0,"outside_temperature":8.83,"return_water_temperature":35.7,"dhw_setpoint_max":65,"dhw_setpoint_min":40,"max_ch_setpoint_max":85,"max_ch_setpoint_min":20,"dhw_setpoint":65,"max_ch_setpoint":85,"burner_starts":12344,"ch_pump_starts":11872,"dhw_pump_starts":8080,"dhw_burner_starts":5088,"burner_operation_hours":1368,"ch_pump_operation_hours":1592,"dhw_pump_operation_hours":6216,"dhw_burner_operation_hours":152}
Feb 21 16:40:16 pi2 homebridge[7545]: [OTGW] send command: PS=1, response: 1
Feb 21 16:40:17 pi2 homebridge[7545]: [Lib] warning: heartbeat 9, drift 701

The summary message is handled before the PS=1 response, but the event handler is installed (using .once()) only after receiving the response. Note that the return message in the log is from the web socket connection, where the code waits for the command response from the http connection used to send the command.

[ebaauw]

Should be fixed in v0.0.33. Fingers crossed. Just to be sure, now logging the raw messages as they come in.