search

BlackZork / mqmgateway

MQTT gateway for modbus networks
GNU Affero General Public License v3.0
42 stars 18 forks source link

Read range of input registers returns just one bogus value instead of json array, two ranges OK #65

Closed marekm72 closed 4 days ago

marekm72 commented 1 week ago

I'm testing mqmgateway-2.8.1 on Debian 12, reading data from Modbus RTU devices with 32 input registers 1-32 (0-31 in raw Modbus frames). The devices are connected via RS485 to MikroTik KNOT used as TCP-to-RTU gateway, polled by Modbus TCP and then data published to local Mosquitto 2.0.18 (from Debian backports) and then viewed by MQTT Explorer.

I'd like to see the 32 Modbus registers as two JSON arrays of 16 values each in MQTT. Possibly later with some conversion but let's start with raw 16-bit integers for now. It seems to work with the below config file (state is shown as an array of two arrays of 16 values). However, if last 3 lines from this config file are deleted, I'd expect to see just one array of 16 integer values, but I actually see only one bogus value (doesn't correspond to any of the input registers). Also, on the last 2 of 3 nodes (node_3 and node_12) state is shown first and availability is below, reverse of node_2 where availability is shown above state (README.md says "Availablity flag is always published before state value.").

modmqttd:
  converter_search_path:
    - /usr/local/lib/modmqttd
  converter_plugins:
    - stdconv.so
modbus:
  networks:
    - name: tcptest
      address: 192.168.1.138
      port: 502
      delay_before_first_command: 50ms
      slaves:
        - address: 2,3,12
          poll_groups:
            - register: 1
              register_type: input
              count: 16
mqtt:
  client_id: modbus
  broker:
    host: localhost
    port: 1883
  objects:
    - topic: ${network}/node_${slave_address}
      slave: 2,3,12
      network: tcptest
      state:
        - register: 1
          register_type: input
          count: 16
        - register: 17
          register_type: input
          count: 16

I'm new to this project and to MQTT, though not new to Modbus (the devices I'm reading were designed and their AVR MCU firmware written by me over 20 years ago), so if there is a better way to achieve what I need, your help would be much appreciated.

BlackZork commented 1 week ago

I understand that there are two problems:

  1. state is published before availability in multislave config for non-first slave
  2. bad values for second state component

Could you try to simplify this config for testing?

Does it still show those two problems?

marekm72 commented 1 week ago

With this simplified config:

modmqttd:
  converter_search_path:
    - /usr/local/lib/modmqttd
  converter_plugins:
    - stdconv.so
modbus:
  networks:
    - name: tcptest
      address: 192.168.1.138
      port: 502
      delay_before_first_command: 50ms
      slaves:
        - address: 2,3
          poll_groups:
            - register: 1
              register_type: input
              count: 2
mqtt:
  client_id: modbus
  broker:
    host: localhost
    port: 1883
  objects:
    - topic: ${network}/node_${slave_address}
      slave: 2,3
      network: tcptest
      state:
        - register: 1
          register_type: input
          count: 2
        - register: 17
          register_type: input
          count: 2

MQTT Explorer shows two arrays, two registers each (correct values) but availability after state:

192.168.1.147
  $SYS
  tcptest
    node_2
      state = [[138,65446],[0,65472]]
      availability = 1
    node_3
      state = [[20289,20585],[33399,35069]]
      availability = 1

After the last 3 lines from that config are removed, single and bogus values (which sometimes change from this modmqttd run to the next):

192.168.1.147
  $SYS
  tcptest
    node_2
      state = 45138
      availability = 1
    node_3
      state = 0
      availability = 1

Log at level 6 (first few seconds):

2024-Sep-04 14:53:19.989001: [INFO ] modmqttd is starting
2024-Sep-04 14:53:19.989521: [DEBUG] Checking "stdconv.so"
2024-Sep-04 14:53:19.989597: [DEBUG] Checking "/usr/local/lib/modmqttd/stdconv.so"
2024-Sep-04 14:53:19.989664: [DEBUG] Trying to load converter plugin from /usr/local/lib/modmqttd/stdconv.so
2024-Sep-04 14:53:19.989940: [INFO ] Added converter plugin std
2024-Sep-04 14:53:19.990054: [DEBUG] Broker configuration initialized
2024-Sep-04 14:53:19.991734: [DEBUG] Adding new register 2.0 (2) type=4 refresh=-1 on network tcptest
2024-Sep-04 14:53:19.992325: [DEBUG] Adding new register 3.0 (2) type=4 refresh=-1 on network tcptest
2024-Sep-04 14:53:19.992399: [DEBUG] 1 modbus client(s) initialized
2024-Sep-04 14:53:19.992914: [DEBUG] processing object tcptest/node_2
2024-Sep-04 14:53:19.993513: [DEBUG] Adding new register 2.0 (2) type=4 refresh=5000 on network tcptest
2024-Sep-04 14:53:19.993681: [DEBUG] object for topic tcptest/node_2 created
2024-Sep-04 14:53:19.993738: [DEBUG] processing object tcptest/node_3
2024-Sep-04 14:53:19.994326: [DEBUG] Adding new register 3.0 (2) type=4 refresh=5000 on network tcptest
2024-Sep-04 14:53:19.994392: [DEBUG] object for topic tcptest/node_3 created
2024-Sep-04 14:53:19.994452: [DEBUG] Finished reading mqtt object declarations
2024-Sep-04 14:53:19.994500: [DEBUG] Extending register 0(2) to 0(2)
2024-Sep-04 14:53:19.994537: [DEBUG] Extending register 0(2) to 0(2)
2024-Sep-04 14:53:19.994570: [DEBUG] Sending register specification to modbus thread for network tcptest
2024-Sep-04 14:53:19.994728: [DEBUG] Performing initial connection to mqtt broker
2024-Sep-04 14:53:19.994767: [INFO ] Connecting to localhost:1883
2024-Sep-04 14:53:19.995127: [DEBUG] Modbus thread started
2024-Sep-04 14:53:19.995185: [TRACE] Waiting for messages
2024-Sep-04 14:53:19.995242: [INFO ] Connecting to 192.168.1.138:502
2024-Sep-04 14:53:19.995280: [INFO ] Response timeout set to 500ms
2024-Sep-04 14:53:19.995315: [DEBUG] Watchdog initialized. Watch period set to 10s
2024-Sep-04 14:53:19.995346: [INFO ] Global minimum delays set. Delay before every command 0ms, delay when slave changes 50ms
2024-Sep-04 14:53:19.995487: [DEBUG] Poll specification set, got 2 slaves,2 registers to poll:
2024-Sep-04 14:53:19.995528: [DEBUG] tcptest, slave 2, register 0:4, count=2, poll every 5000ms, min f_delay 0ms, min delay 0ms
2024-Sep-04 14:53:19.995565: [DEBUG] tcptest, slave 3, register 0:4, count=2, poll every 5000ms, min f_delay 0ms, min delay 0ms
2024-Sep-04 14:53:19.995660: [TRACE] Starting election for silence period 360000000000ms
2024-Sep-04 14:53:19.995707: [TRACE] Next register to poll set to 2.0, commands_left=2
2024-Sep-04 14:53:19.995739: [DEBUG] starting initial poll
2024-Sep-04 14:53:19.995780: [INFO ] modbus: connecting
2024-Sep-04 14:53:19.995908: [DEBUG] Waiting for connection event
2024-Sep-04 14:53:19.996038: [DEBUG] Client modbus received CONNACK (0)
2024-Sep-04 14:53:19.996093: [INFO ] Connection established
2024-Sep-04 14:53:19.996124: [INFO ] Mqtt connected, sending subscriptions…
2024-Sep-04 14:53:19.996187: [INFO ] Mqtt ready to process messages
2024-Sep-04 14:53:19.996383: [INFO ] modbus: connected
2024-Sep-04 14:53:19.996434: [INFO ] Waiting for mqtt network to become online
2024-Sep-04 14:53:19.996468: [TRACE] Watchdog: current error period is 0ms
2024-Sep-04 14:53:19.996499: [TRACE] Waiting for messages
2024-Sep-04 14:53:19.996582: [DEBUG] Broker connected, entering main loop
2024-Sep-04 14:53:20.029941: [TRACE] Register 2.0 (0x2.0x0) polled in 33ms
2024-Sep-04 14:53:20.030092: [TRACE] Register 2.0 values sent, data=[8b][ffa4]
2024-Sep-04 14:53:20.030143: [TRACE] Watchdog: current error period is 0ms
2024-Sep-04 14:53:20.030176: [TRACE] Checking for incoming message
2024-Sep-04 14:53:20.030368: [DEBUG] Publish on topic tcptest/node_2/state: 45138
2024-Sep-04 14:53:20.030425: [DEBUG] Client modbus sending PUBLISH (d0, q0, r1, m1, 'tcptest/node_2/state', ... (5 bytes))
2024-Sep-04 14:53:20.030469: [DEBUG] Client modbus sending PUBLISH (d0, q0, r1, m2, 'tcptest/node_2/availability', ... (1 bytes))
2024-Sep-04 14:53:20.065039: [TRACE] Register 3.0 (0x3.0x0) polled in 34ms
2024-Sep-04 14:53:20.065136: [TRACE] Register 3.0 values sent, data=[4f40][5071]
2024-Sep-04 14:53:20.065180: [INFO ] Initial poll done in 69ms
2024-Sep-04 14:53:20.065215: [TRACE] Watchdog: current error period is 0ms
2024-Sep-04 14:53:20.065247: [TRACE] Checking for incoming message
2024-Sep-04 14:53:20.065387: [DEBUG] Publish on topic tcptest/node_3/state: 0
2024-Sep-04 14:53:20.065429: [DEBUG] Client modbus sending PUBLISH (d0, q0, r1, m3, 'tcptest/node_3/state', ... (1 bytes))
2024-Sep-04 14:53:20.065481: [DEBUG] Client modbus sending PUBLISH (d0, q0, r1, m4, 'tcptest/node_3/availability', ... (1 bytes))
2024-Sep-04 14:53:20.065532: [TRACE] Wait duration set to 4964ms as next poll for register 2.0 (0x2.0x0)
2024-Sep-04 14:53:20.065571: [TRACE] Scheduling 0 registers to execute, next schedule in 4964ms
2024-Sep-04 14:53:20.065605: [TRACE] Watchdog: current error period is 0ms
2024-Sep-04 14:53:20.065654: [TRACE] Waiting for messages for  4964ms
2024-Sep-04 14:53:25.030511: [TRACE] Register 2.0 (0x2.0x0) added, last read 5000ms ago
2024-Sep-04 14:53:25.055651: [TRACE] Wait duration set to 5000ms as next poll for register 2.0 (0x2.0x0)
2024-Sep-04 14:53:25.055733: [TRACE] Wait duration set to 34ms as next poll for register 3.0 (0x3.0x0)
2024-Sep-04 14:53:25.055783: [TRACE] Starting election for silence period 4990ms
2024-Sep-04 14:53:25.055845: [TRACE] Next register to poll set to 2.0, commands_left=2
2024-Sep-04 14:53:25.055878: [TRACE] Scheduling 1 registers to execute, next schedule in 34ms
2024-Sep-04 14:53:25.089209: [TRACE] Register 2.0 (0x2.0x0) polled in 33ms
2024-Sep-04 14:53:25.089319: [TRACE] Watchdog: current error period is 0ms
2024-Sep-04 14:53:25.089353: [TRACE] Checking for incoming message
2024-Sep-04 14:53:25.089597: [TRACE] Wait duration set to 4999ms as next poll for register 2.0 (0x2.0x0)
2024-Sep-04 14:53:25.089637: [TRACE] Register 3.0 (0x3.0x0) added, last read 5024ms ago
2024-Sep-04 14:53:25.089682: [TRACE] Starting election for silence period 0ms
2024-Sep-04 14:53:25.089735: [TRACE] Next register to poll set to 3.0, commands_left=2
2024-Sep-04 14:53:25.089767: [TRACE] Scheduling 1 registers to execute, next schedule in 4999ms
2024-Sep-04 14:53:25.122887: [TRACE] Register 3.0 (0x3.0x0) polled in 33ms
2024-Sep-04 14:53:25.123032: [DEBUG] Publish on topic tcptest/node_3/state: 0
2024-Sep-04 14:53:25.123077: [DEBUG] Client modbus sending PUBLISH (d0, q0, r1, m5, 'tcptest/node_3/state', ... (1 bytes))
2024-Sep-04 14:53:25.123126: [TRACE] Register 3.0 values sent, data=[4f40][506d]
2024-Sep-04 14:53:25.123169: [TRACE] Watchdog: current error period is 0ms
2024-Sep-04 14:53:25.123201: [TRACE] Checking for incoming message
2024-Sep-04 14:53:25.123438: [TRACE] Watchdog: current error period is 0ms
2024-Sep-04 14:53:25.123479: [TRACE] Waiting for messages for  4965ms

The data= hex values in the log look like correct register contents (slowly changing values from analog temperature sensors), but I don't see them published. I haven't run this for a long time but the bogus values don't seem to change later after modmqttd startup, while they change from one startup to the next.

BlackZork commented 1 week ago

Thanks, I will try to reproduce this in unit tests.

As for availability flag this is a documentation error. State value is published first, availability next. The idea is that if you receive availability=1 you can assume that previously received state value is valid. Fixed in #7a1fcf2a - I hope that the new description explains this behavior.

marekm72 commented 1 week ago

Previously tested with the 2.8.1 release, now tested again with the latest "git clone https://github.com/BlackZork/mqmgateway.git" (the "#branch=master" part removed as git reported an error). So the order seems to be consistent now (availability last), but I can confirm the bug with single bogus values instead of arrays is still there (tested with the same config files as posted above).

BlackZork commented 1 week ago

I was able to reproduce this bug in unit tests. It works if there is a registers keyword under state:

      state:
        registers:
            - register: 1
              register_type: input
              count: 2

but it does not work in original example.

BlackZork commented 1 week ago

but it does not work in original example.

After looking deeper into this it turns out that 2.8.1 does not support yaml register lists with single element only, with "registers" below state returned value is ok, but is returned as string instead of a list.

BlackZork commented 4 days ago

Handling of single element json lists fixed in 6b95575