ccutrer / waterfurnace_aurora

Library for communication with WaterFurnace Aurora control systems
30 stars 7 forks source link

Unable to fetch modbus registers with aurora_fetch: "execution expired (ModBus::Errors::ModBusTimeout)" #58

Open larsjohannessen opened 7 months ago

larsjohannessen commented 7 months ago

First off, really handy tool - thanks for releasing it.

I've had some small successes querying a limited number of registers and have successfully gotten data back:

$ aurora_fetch /dev/ttyUSB0 745-746

Heating Set Point (745): 62.0°F
Cooling Set Point (746): 75.0°F

Unfortunately, when I try to query a larger number of registers, I get the following ModBus::Errors::ModBusTimeout errors:

$ aurora_fetch /dev/ttyUSB0 valid --yaml > myheatpump.yml

I, [2023-12-27T18:23:08.392344 #909]  INFO -- : Fetching register(s) 0..100...
Traceback (most recent call last):
    24: from /usr/local/bin/aurora_fetch:23:in `<main>'
    23: from /usr/local/bin/aurora_fetch:23:in `load'
    22: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/exe/aurora_fetch:60:in `<top (required)>'
    21: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:73:in `query_registers'
    20: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:73:in `each'
    19: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:74:in `block in query_registers'
    18: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:81:in `rescue in block in query_registers'
    17: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:81:in `each'
    16: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:82:in `block (2 levels) in query_registers'
    15: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:91:in `rescue in block (2 levels) in query_registers'
    14: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:91:in `each'
    13: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:93:in `block (3 levels) in query_registers'
    12: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/modbus/slave.rb:26:in `[]'
    11: from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/proxy.rb:13:in `[]'
    10: from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/client/slave.rb:178:in `read_holding_register'
     9: from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/client/slave.rb:174:in `read_holding_registers'
     8: from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/client/slave.rb:267:in `query'
     7: from /usr/lib/ruby/2.7.0/timeout.rb:105:in `timeout'
     6: from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/client/slave.rb:269:in `block in query'
     5: from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/rtu_slave.rb:32:in `read_pdu'
     4: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/modbus/slave.rb:35:in `read_rtu_response'
     3: from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/rtu.rb:43:in `read'
     2: from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/rtu.rb:43:in `loop'
     1: from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/rtu.rb:47:in `block in read'
/var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/rtu.rb:47:in `wait_readable': execution expired (ModBus::Errors::ModBusTimeout)
    17: from /usr/local/bin/aurora_fetch:23:in `<main>'
    16: from /usr/local/bin/aurora_fetch:23:in `load'
    15: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/exe/aurora_fetch:60:in `<top (required)>'
    14: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:73:in `query_registers'
    13: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:73:in `each'
    12: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:74:in `block in query_registers'
    11: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:81:in `rescue in block in query_registers'
    10: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:81:in `each'
     9: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:82:in `block (2 levels) in query_registers'
     8: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:91:in `rescue in block (2 levels) in query_registers'
     7: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:91:in `each'
     6: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:93:in `block (3 levels) in query_registers'
     5: from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/modbus/slave.rb:26:in `[]'
     4: from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/proxy.rb:13:in `[]'
     3: from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/client/slave.rb:178:in `read_holding_register'
     2: from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/client/slave.rb:174:in `read_holding_registers'
     1: from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/client/slave.rb:266:in `query'
/var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/client/slave.rb:275:in `rescue in query': Timed out during read attempt (ModBus::Errors::ModBusTimeout)

Is there something I can do to extend the timeout period? I believe I'm executing the aurora_fetch command correctly, and am trying to follow the section of the README.md that begins with "This is the easiest way to make a "dump" of your system to send if you're having problems".

Please let me know if there's any other information I can provide to assist with debugging. This looks like a really useful tool! To that end, here is some other generic information you might find useful:

$ cat /etc/os-release 

PRETTY_NAME="Debian GNU/Linux 11 (bullseye)"
NAME="Debian GNU/Linux"
VERSION_ID="11"
VERSION="11 (bullseye)"
VERSION_CODENAME=bullseye
ID=debian
HOME_URL="https://www.debian.org/"
SUPPORT_URL="https://www.debian.org/support"
BUG_REPORT_URL="https://bugs.debian.org/"
$ uname -a

Linux rpi-waterfurnace 6.1.21-v8+ #1642 SMP PREEMPT Mon Apr  3 17:24:16 BST 2023 aarch64 GNU/Linux
$ journalctl -u water_furnace_monitor

Dec 27 18:35:06 rpi-waterfurnace systemd[1]: Started Aurora MQTT Bridge.
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]: /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/client/slave.rb:275:in `rescue in query': Timed out during read attempt (ModBus::>
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/client/slave.rb:266:in `query'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/modbus/slave.rb:12:in `read_multiple_holding_registers'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/modbus/slave.rb:28:in `[]'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:157:in `initialize'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/exe/aurora_mqtt_bridge:42:in `new'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/exe/aurora_mqtt_bridge:42:in `<top (required)>'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /usr/local/bin/aurora_mqtt_bridge:23:in `load'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /usr/local/bin/aurora_mqtt_bridge:23:in `<main>'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]: /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/rtu_slave.rb:44:in `sleep': execution expired (ModBus::Errors::ModBusTimeout)
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/rtu_slave.rb:44:in `block in read_pdu'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/rtu_slave.rb:42:in `loop'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/rtu_slave.rb:42:in `read_pdu'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/client/slave.rb:269:in `block in query'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /usr/lib/ruby/2.7.0/timeout.rb:105:in `timeout'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/rmodbus-ccutrer-2.1.0/lib/rmodbus/client/slave.rb:267:in `query'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/modbus/slave.rb:12:in `read_multiple_holding_registers'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/modbus/slave.rb:28:in `[]'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/lib/aurora/abc_client.rb:157:in `initialize'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/exe/aurora_mqtt_bridge:42:in `new'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /var/lib/gems/2.7.0/gems/waterfurnace_aurora-1.4.8/exe/aurora_mqtt_bridge:42:in `<top (required)>'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /usr/local/bin/aurora_mqtt_bridge:23:in `load'
Dec 27 18:35:37 rpi-waterfurnace aurora_mqtt_bridge[2435]:         from /usr/local/bin/aurora_mqtt_bridge:23:in `<main>'
Dec 27 18:35:37 rpi-waterfurnace systemd[1]: aurora_mqtt_bridge.service: Main process exited, code=exited, status=1/FAILURE
Dec 27 18:35:37 rpi-waterfurnace systemd[1]: aurora_mqtt_bridge.service: Failed with result 'exit-code'.
Dec 27 18:35:37 rpi-waterfurnace systemd[1]: aurora_mqtt_bridge.service: Consumed 1.594s CPU time.
$ cat /proc/cpuinfo | grep -v "Serial"
processor   : 0
BogoMIPS    : 38.40
Features    : fp asimd evtstrm crc32 cpuid
CPU implementer : 0x41
CPU architecture: 8
CPU variant : 0x0
CPU part    : 0xd03
CPU revision    : 4

processor   : 1
BogoMIPS    : 38.40
Features    : fp asimd evtstrm crc32 cpuid
CPU implementer : 0x41
CPU architecture: 8
CPU variant : 0x0
CPU part    : 0xd03
CPU revision    : 4

processor   : 2
BogoMIPS    : 38.40
Features    : fp asimd evtstrm crc32 cpuid
CPU implementer : 0x41
CPU architecture: 8
CPU variant : 0x0
CPU part    : 0xd03
CPU revision    : 4

processor   : 3
BogoMIPS    : 38.40
Features    : fp asimd evtstrm crc32 cpuid
CPU implementer : 0x41
CPU architecture: 8
CPU variant : 0x0
CPU part    : 0xd03
CPU revision    : 4

Hardware    : BCM2835
Revision    : a020d3
Model       : Raspberry Pi 3 Model B Plus Rev 1.3
larsjohannessen commented 7 months ago

Through a day or two of trial and error, I have found that I can almost reliably (75% of the time) dump stats in 10-20 register chunks if I break the list of registers I'm trying to dump up into the following groups (expressed in Python list[] format).

register_chunks = ["1,2,6,9,15,16,19,20,25,26",
"30,31,33,84,85,88-110,112,209,282",
"321-323,325,340-342,344,346,347,362",
"400,401,404,412,413,419,501,502,565,567",
"740,741,745-747,813,900,901,903,908",
"1103-1117,1119",
"1124-1126,1134-1136,1146-1157,1164,1165,3000,3001",
"3322,3323,3325-3327,3330-3332,3422-3425,3522-3524,3808,3903-3906",
"12_005,12_006,12_309,12_310,31_003,31_007,31_008,31_009,31_010,31_013,31_016,31_019,31_022,31_109,31_110,31_200"]

Then, using a loop, I can iterate through the list and feed each chunk to aurora_fetch and usually get responses (about 50% of the time) without a timeout. If I add a 3-5 second sleep() at the end of each loop iteration to force a pause between successive calls to aurora_fetch, that gets me up to about a 75% success rate.

Admittedly, this is a bit of a hack, so any thoughts on how to make aurora_fetch perform more reliably/not timeout would be welcome!