networkupstools / nut

The Network UPS Tools repository. UPS management protocol Informational RFC 9271 published by IETF at https://www.rfc-editor.org/info/rfc9271 Please star NUT on GitHub, this helps with sponsorships!
https://networkupstools.org/
Other
1.94k stars 346 forks source link

Add support for new APC Modbus protocol #139

Closed aquette closed 11 months ago

aquette commented 10 years ago

From APCUPSD (http://apcupsd.cvs.sourceforge.net/viewvc/apcupsd/apcupsd/ReleaseNotes?pathrev=Release-3_14_11): "APC publicly released documentation[1] on a new UPS control and monitoring protocol, loosely referred to as MODBUS (after the historic industrial control protocol it is based on). The new protocol operates over RS232 serial lines as well as USB connections and is intended to supplement APC's proprietary Microlink protocol. Microlink is not going away, but APC has realized that third parties require access to UPS status and control information. Rather than publicly open Microlink, they have created another protocol to operate along side it.

Many existing Microlink UPSes can be upgraded to support MODBUS via a firmware update. See [2]. Certain older models are not upgradeable. APC support will be your best contact for determining if your UPS supports a MODBUS upgrade the information linked below does not make it clear."

[1] http://www.apc.com/whitepaper/?an=176 [2] http://www.schneider-electric.us/support/index?page=content&country=ITB&lang=EN&id=FA164737 [3] http://www.apcupsd.com/manual/manual.html


Add support for MODBUS over RS232 and USB in NUT. This effort must be synchronized with the general Modbus support in NUT ( #50 )


Implementation notes:

EchterAgo commented 11 months ago

Great to hear this.

Good to see that it reads the delays correctly on yours:

   0.196059     [D5] send_to_all: SETINFO ups.delay.shutdown "180"
   0.196089     [D5] send_to_all: SETINFO ups.delay.start "0"
   0.196120     [D5] send_to_all: SETINFO ups.delay.reboot "8"

On mine it somehow reads 0 here despite there being a delay when doing shutdown, maybe a firmware bug, I'll try upgrading to latest soon.

All looks pretty good. battery.date.maintenance is not what I see on the front panel, I see battery.date which is what I set when I replaced the batteries last.

This is what I used for battery.date.maintenance:

image

And this is what I used for battery.date:

image

On my unit battery.date matches what I can see in the menu, not sure how battery.date.maintenance is calculated though. I wonder why your maintenance timestamp is before the installation timestamp.

Thanks for the dev work! Make sure the readme for this driver includes the (obvious) step to enable Modbus on the device itself.

You're welcome. Yes, there should be a section on how to enable Modbus in the manual page.

I will follow this ticket for a stable enough commit to build and run this on my main system.

Note that at least on Debian you can build it like this and integrate it with the Debian package by copying the apc_modbus driver into /lib/nut:

./configure \
    --with-drivers=usbhid-ups,apc_modbus \
    --with-usb \
    --prefix= --sysconfdir=/etc/nut --with-statepath=/run/nut \
    --with-user=nut --with-group=nut \
    --with-modbus --with-modbus-includes=-I/home/ago/src/libmodbus/prefix/include/modbus --with-modbus-libs="-L/home/ago/src/libmodbus/prefix/lib -lmodbus"

Note that you'll have to keep around the libmodbus prefix for that to work.

WiredWonder commented 11 months ago

Thanks, have done that!

Would it be possible to get Output.ApparentPowerRating and Output.RealPowerRating, or ideally return output.power as Output.RealPowerRating * Output[0].RealPower_Pct? It'd be nice to record load in W not %.

Not sure how other nut drivers handle this.

edit:

This is what I used for battery.date.maintenance: And this is what I used for battery.date:

nut battery.date (modus Battery.DateSetting) is definitely when I changed the batteries. I am not sure what battery.date.maintenance (modbus Battery.Date) is referring to. It's approx 2 years after manufacture.

jimklimov commented 11 months ago

When nothing else helps, RTFM ;)

Per https://networkupstools.org/docs/developer-guide.chunked/apas02.html :

The *.power reports should be "apparent power (Volt-Amps)" and for Watts there's *.realpower as "real power (Watts)".

WiredWonder commented 11 months ago

Thanks, seems like they are mapped to the correct nut name!

The *.power reports should be "apparent power (Volt-Amps)" and for Watts there's *.realpower as "real power (Watts)".

Currently the driver is reporting the device values directly which are a % of total available capacity. The device also reports capacity, so the value in Watts/VA could be calculated.

Current load is about 180W

ups.power: 29.04
ups.realpower: 29.40
EchterAgo commented 11 months ago

@galapogos01 I pushed a commit that changes power/realpower to absolute numbers. Edit: Also added the nominal values.

WiredWonder commented 11 months ago

Great work! Looking good here.

ups.power: 218.00
ups.power.nominal: 750.00
ups.realpower: 173.86
ups.realpower.nominal: 600.00

Thank you so much again - it's great to see these very popular models finally get proper support in nut.

PrplHaz4 commented 11 months ago

@PrplHaz4 thanks, both of those should work, it would be interesting to test the X version because it has a higher firmware version than mine (9.x)

Great work! Amazing to see this coming alive after 9yrs! 🥇

Does Modbus TCP output help at all?

Modbus TCP Debug ``` root@4d037edb731c:/srcnut# NUT_DEBUG_LEVEL=5 NUT_CONFPATH=/srcnut NUT_STATEPATH=/srcnut/state /srcnut/drivers/apc_modbus -F -a apcups Network UPS Tools - NUT APC Modbus driver 0.01 (2.8.0-2602-g095bd306e) Debug level is 0, dump data count is off, but backgrounding mode requested as off Defaulting debug verbosity to NUT_DEBUG_LEVEL=5 since none was requested by command-line options 0.000022 [D1] Network UPS Tools version 2.8.0-2602-g095bd306e (release/snapshot of 2.8.0.1) built with gcc (Debian 10.2.1-6) 10.2.1 20210110 and configured with flags: --with-drivers=apc_modbus --with-usb --with-modbus --with-modbus-includes=-I/build/libmodbus/include/modbus --with-modbus-libs='-L/build/libmodbus/lib -lmodbus' 0.000055 [D1] debug level is '5' 0.000059 [D5] send_to_all: SETINFO driver.debug "5" 0.000075 [D5] send_to_all: SETFLAGS driver.debug RW NUMBER 0.000288 [D1] Succeeded to become_user(nobody): now UID=65534 GID=65534 0.000312 [D5] send_to_all: SETINFO device.type "ups" 0.000329 [D5] send_to_all: SETINFO driver.state "init.device" Connecting to [192.168.4.27]:502 0.005833 [D5] send_to_all: SETINFO driver.state "init.quiet" 0.005876 [D5] send_to_all: SETINFO driver.version "2.8.0-2602-g095bd306e" 0.005910 [D5] send_to_all: SETINFO driver.version.internal "0.01" 0.005913 [D5] send_to_all: SETINFO driver.name "apc_modbus" 0.005917 [D5] send_to_all: SETINFO driver.state "init.info" [00][01][00][00][00][06][01][03][02][04][00][58] Waiting for a confirmation... <00><01><00><00><00><01><03><55><50><53><20><31><35><2E><30><20><20><20><20><20><20><20><20><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><53><6D><61><72><74><2D><55><50><53><20><58><20><31><35><30><30><20><20><20><20><20><20><20><20><20><20><20><20><20><20><20><20><53><4D><58><31><35><30><30><52><4D><32><55><20><20><20><20><20><20><20><20><20><20><20><20><20><20><20><20><20><20><20><20><20><41><53><31><38><33><30><31><33><37><30><31><35><20><20><20><20><41><50><43><52><42><43><31><31><35><20><20><20><20><20><20><20><53><4D><58><34><38><52><4D><42><50><32><55><20><20><20><20><20><05><04><00><0E><1A><7F><00><02><00><00><00><00><21><75><70><73><2D><61><70><63><2D><30><32><20><20><20><20><20><20> 0.221131 [D5] send_to_all: SETINFO ups.firmware "UPS 15.0" 0.221150 [D5] send_to_all: SETINFO ups.model "Smart-UPS X 1500" 0.221156 [D5] send_to_all: SETINFO ups.serial "xxxx" 0.221164 [D5] send_to_all: SETINFO ups.power.nominal "1440.00" 0.221170 [D5] send_to_all: SETINFO ups.realpower.nominal "1200.00" 0.221269 [D5] send_to_all: SETINFO ups.mfr.date "2018-07-28" 0.221320 [D5] send_to_all: SETINFO battery.date "2023-08-15" 0.221328 [D5] send_to_all: SETINFO ups.id "ups-apc-02" 0.221334 [D5] send_to_all: SETINFO ups.mfr "American Power Conversion" 0.221341 [D5] send_to_all: SETINFO driver.state "init.updateinfo" [00][02][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><02><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> 0.570370 [D5] send_to_all: SETINFO input.transfer.reason "AcceptableInput" [00][03][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><03><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0F><00><01><0E><0C><4E><00><00><0C><37><00><00><00><2E><00><00><1E><52><00><00><1E><03><00><32><57><36><00><00><00><00><00><00><00><01><1E><52><00><00><00><00><2D><60><00><00><00><00><00><00><00><00> 0.931542 [D5] send_to_all: SETINFO battery.runtime "19318" 0.931562 [D5] send_to_all: SETINFO battery.charge "100.00" 0.931569 [D5] send_to_all: SETINFO battery.voltage "54.50" 0.931579 [D5] send_to_all: SETINFO battery.date.maintenance "2028-01-29" 0.931585 [D5] send_to_all: SETINFO battery.temperature "29.84" 0.931591 [D5] send_to_all: SETINFO ups.load "12.30" 0.931598 [D5] send_to_all: SETINFO ups.realpower "147.66" 0.931650 [D5] send_to_all: SETINFO ups.power "175.89" 0.931659 [D5] send_to_all: SETINFO output.current "1.44" 0.931666 [D5] send_to_all: SETINFO output.voltage "121.28" 0.931693 [D5] send_to_all: SETINFO output.frequency "60.02" 0.931741 [D5] send_to_all: SETINFO experimental.output.energy "3299126" 0.931793 [D5] send_to_all: SETINFO input.voltage "121.28" 0.931843 [D5] send_to_all: SETINFO ups.efficiency "90.8" 0.931890 [D5] send_to_all: SETINFO ups.timer.shutdown "0" 0.931937 [D5] send_to_all: SETINFO ups.timer.start "0" 0.931946 [D5] send_to_all: SETINFO ups.timer.reboot "0" [00][04][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><04><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 1.280720 [D5] send_to_all: SETINFO input.transfer.high "127" 1.280735 [D5] send_to_all: SETINFO input.transfer.low "106" 1.280742 [D5] send_to_all: SETINFO ups.delay.shutdown "0" 1.280747 [D5] send_to_all: SETINFO ups.delay.start "0" 1.280796 [D5] send_to_all: SETINFO ups.delay.reboot "0" 1.280810 [D5] send_to_all: SETINFO ups.status "OL HE" 1.280816 [D5] send_to_all: DATAOK 1.280823 [D5] send_to_all: SETINFO driver.state "init.quiet" Fatal error: unable to create listener socket bind /srcnut/state/apc_modbus-apcups failed: Permission denied 1.281207 Exiting. 1.281234 [D5] send_to_all: SETINFO driver.state "cleanup.upsdrv" 1.281342 [D5] send_to_all: SETINFO driver.state "cleanup.exit" 1.281396 upsnotify: failed to notify about state 4: no notification tech defined, will not spam more about it ```
EchterAgo commented 11 months ago

@PrplHaz4 it is great to know it is working, thanks for testing! What would also be of interest is whether reconnection is handled well. Like if you remove the cable and it times out or if the UPS closes the connection (not sure how to test that).

As for your bind /srcnut/state/apc_modbus-apcups failed: Permission denied error, you probably need to adjust permissions or just set NUT_STATEPATH=/tmp which should work as well.

PrplHaz4 commented 11 months ago

@PrplHaz4 it is great to know it is working, thanks for testing! What would also be of interest is whether reconnection is handled well. Like if you remove the cable and it times out or if the UPS closes the connection (not sure how to test that).

As for your bind /srcnut/state/apc_modbus-apcups failed: Permission denied error, you probably need to adjust permissions or just set NUT_STATEPATH=/tmp which should work as well.

Thanks for the tip on /tmp - that worked to keep it running. I put the full build in a docker container, so other things might be going on, but after some time (maybe 5 mins?) the TCP connection times out and seems to loop on error (logs below). the TCP timeout might be a valid failure mode in general. I'll work on a plug/replug USB test as well.

Modbus TCP Debug ``` <01><3D><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> [01][3E][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><3E><00><00><00><43><01><03><40><00><00><42><00><06><00><00><28><0E><00><01><0F><60><0E><4A><00><00><0C><36><00><00><00><2D><00><00><1E><86><00><00><1E><03><00><32><6F><5F><00><00><00><00><00><00><00><01><1E><86><00><00><00><00><2E><80><00><00><00><00><00><00><00><00> 210.065685 [D5] send_to_all: SETINFO battery.temperature "30.75" 210.065706 [D5] send_to_all: SETINFO ups.load "14.29" 210.065710 [D5] send_to_all: SETINFO ups.realpower "171.47" 210.065713 [D5] send_to_all: SETINFO ups.power "175.84" 210.065716 [D5] send_to_all: SETINFO output.current "1.41" 210.065738 [D5] send_to_all: SETINFO output.voltage "122.09" 210.065757 [D5] send_to_all: SETINFO output.frequency "60.02" [01][3F][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><3F><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 210.425786 [D5] send_to_all: SETINFO driver.state "quiet" 211.443649 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][40][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><40><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> [01][41][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><41><00><00><00><43><01><03><40><00><00><46><00><06><00><00><28><0E><00><01><0F><60><11><77><00><00><0C><00><00><00><30><00><00><1E><86><00><00><1E><03><00><32><6F><5F><00><00><00><00><00><00><00><01><1E><86><00><00><00><00><2E><60><00><00><00><00><00><00><00><00> 212.085596 [D5] send_to_all: SETINFO battery.runtime "18156" 212.085606 [D5] send_to_all: SETINFO battery.voltage "54.50" 212.085613 [D5] send_to_all: SETINFO ups.load "17.46" 212.085615 [D5] send_to_all: SETINFO ups.realpower "209.58" 212.085618 [D5] send_to_all: SETINFO ups.power "187.09" 212.085620 [D5] send_to_all: SETINFO output.current "1.50" 212.085625 [D5] send_to_all: SETINFO ups.efficiency "92.8" [01][42][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... ERROR Connection timed out: select 212.586686 _apc_modbus_read_registers: Read of 1026:1033 failed: Connection timed out (192.168.4.27:502) 212.586705 [D2] Communication errors: 1 212.586713 [D5] send_to_all: DATASTALE 212.586762 [D5] send_to_all: SETINFO driver.state "quiet" 213.444582 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][43][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><42><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x142 (not 0x143) 213.444702 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][44][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><43><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x143 (not 0x144) 213.814720 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][45][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><44><00><00><00><43><01><03><40><00><00><3F><44><00><06><00><00><28><0E><00><01><0F><60><10><00><00><0B><9C><00><00><00><2B><00><00><1E><86><00><00><1E><03><00><32><6F><5F><00><00><00><00><00><00><00><01><1E><86><00><00><00><00><2E><60><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x144 (not 0x145) 214.120354 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 214.120394 [D2] Communication errors: 3 214.120400 [D5] send_to_all: SETINFO driver.state "quiet" 215.446092 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][46][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><45><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x145 (not 0x146) 215.446255 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][47][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><46><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x146 (not 0x147) 215.764975 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][48][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><47><00><00><00><43><01><03><40><00><00><42><00><06><00><00><28><0E><00><01><0F><5D><0E><4A><00><00><0C><00><00><00><2F><00><00><1E><8C><00><00><1E><03><00><32><6F><5F><00><00><00><00><00><00><00><01><1E><86><00><00><00><00><2E><60><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x147 (not 0x148) 216.075836 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 216.075858 [D2] Communication errors: 3 216.075865 [D5] send_to_all: SETINFO driver.state "quiet" 217.447582 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][49][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><48><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x148 (not 0x149) 217.447894 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][4A][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><49><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x149 (not 0x14A) 217.705309 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][4B][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><4A><00><00><00><43><01><03><40><00><00><3F><44><00><06><00><00><28><0E><00><01><0F><60><0E><00><00><0C><00><00><00><2F><00><00><1E><86><00><00><1E><03><00><32><6F><5F><00><00><00><00><00><00><00><01><1E><86><00><00><00><00><2E><80><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x14A (not 0x14B) 218.046276 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 218.046328 [D2] Communication errors: 3 218.046346 [D5] send_to_all: SETINFO driver.state "quiet" 219.449228 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][4C][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><4B><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x14B (not 0x14C) 219.449407 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][4D][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><4C><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x14C (not 0x14D) 219.755749 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][4E][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><4D><00><00><00><43><01><03><40><00><00><42><00><06><00><00><28><0E><00><01><0F><60><0B><83><00><00><0B><04><00><00><00><28><00><00><1E><86><00><00><1E><02><00><32><6F><5F><00><00><00><00><00><00><00><01><1E><86><00><00><00><00><2E><60><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x14D (not 0x14E) 220.066876 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 220.066908 [D2] Communication errors: 3 220.066939 [D5] send_to_all: SETINFO driver.state "quiet" 221.450720 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][4F][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><4E><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x14E (not 0x14F) 221.450989 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][50][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><4F><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x14F (not 0x150) 221.736264 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][51][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><50><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0E><00><01><0F><5D><0B><1D><00><00><0A><00><00><00><28><00><00><1E><8C><00><00><1E><02><00><32><6F><5F><00><00><00><00><00><00><00><01><1E><8C><00><00><00><00><2E><20><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x150 (not 0x151) 222.107774 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 222.107781 [D2] Communication errors: 3 222.107788 [D5] send_to_all: SETINFO driver.state "quiet" 223.452348 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][52][00][00][00][06][01][03][00][00][00][1B] ```
EchterAgo commented 11 months ago
Invalid transaction ID received 0x142 (not 0x143)

This indicates that it is getting a response to a previous command. There likely needs to be a buffer flush somewhere. I just pushed a commit for testing that does buffer flushing on reconnect and open.

EetuRasilainen commented 11 months ago

Do I need the patched libmodbus if I am using ModBus over a serial link (with APC AP940-0625A cable)? As far as I understand the patched libmodbus is only required for Modbus-over-USB.

Right now I am querying my SMT1500 using a custom Python script and pymodbus through this serial cable but I'd prefer to use NUT for this.

EchterAgo commented 11 months ago

@EetuRasilainen you don't need a patched libmodbus for serial.

PrplHaz4 commented 11 months ago
Invalid transaction ID received 0x142 (not 0x143)

This indicates that it is getting a response to a previous command. There likely needs to be a buffer flush somewhere. I just pushed a commit for testing that does buffer flushing on reconnect and open.

Thanks again! Still seeing these on 10071db after about 5 mins.

Modbus TCP Debug ``` Waiting for a confirmation... <01><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0E><00><01><0E><9D><12><00><00><0D><00><00><00><34><00><00><1E><58><00><00><1E><02><00><32><78><58><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2D><00><00><00><00><00><00><00><00> 298.235534 [D5] send_to_all: SETINFO battery.voltage "54.50" 298.235547 [D5] send_to_all: SETINFO battery.temperature "29.23" 298.235566 [D5] send_to_all: SETINFO ups.load "18.66" 298.235570 [D5] send_to_all: SETINFO ups.realpower "223.88" 298.235587 [D5] send_to_all: SETINFO ups.power "200.70" 298.235590 [D5] send_to_all: SETINFO output.current "1.62" 298.235593 [D5] send_to_all: SETINFO output.voltage "121.38" 298.235597 [D5] send_to_all: SETINFO input.voltage "121.38" [01][C3][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 298.584090 [D5] send_to_all: SETINFO driver.state "quiet" 299.593432 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][C4][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> [01][C5][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... ERROR Connection timed out: select 300.394893 _apc_modbus_read_registers: Read of 128:160 failed: Connection timed out (192.168.4.27:502) [01][C6][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><00><00><00><43><01><03><40><00><00><46><00><06><00><00><28><0E><00><01><0E><0D><19><00><00><0B><07><00><00><00><29><00><00><1E><58><00><00><1E><03><00><32><78><58><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2E><20><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x1C5 (not 0x1C6) 300.398689 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 300.398709 [D2] Communication errors: 2 300.398724 [D5] send_to_all: DATASTALE 300.398730 [D5] send_to_all: SETINFO driver.state "quiet" 301.594838 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][C7][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x1C6 (not 0x1C7) 301.595072 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][C8][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x1C7 (not 0x1C8) 301.872993 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][C9][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><00><00><00><43><01><03><40><00><00><46><00><06><00><00><28><0E><00><01><0E><9D><0B><1D><00><00><0B><33><00><00><00><29><00><00><1E><58><00><00><1E><03><00><32><78><58><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2E><20><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x1C8 (not 0x1C9) 302.284140 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 302.284159 [D2] Communication errors: 3 302.284173 [D5] send_to_all: SETINFO driver.state "quiet" 303.596205 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][CA][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x1C9 (not 0x1CA) 303.596408 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][CB][00][00][00][06][01][03][00][80][00][20] ```
EchterAgo commented 11 months ago

Still looks like it receives a response packet that was expected for the previous command.

Could you maybe do a Wireshark / tcpdump packet capture on the Modbus port or the UPS IP address and send it to me privately (derago at gmail.com)? For tcpdump you can do tcpdump -s 1500 -w modbus.cap port 502, I need the modbus.cap this creates.

I asked APC/SE to send me a NMC to test this but so far they only replied telling me where to buy one, and I'm not going to spend multiple hundred bucks on that :\

Maybe I should try to make a RS232 to TCP Modbus converter on a Raspberry Pi Pico.

EchterAgo commented 11 months ago

There is also something very similar here: https://github.com/stephane/libmodbus/issues/525, https://github.com/stephane/libmodbus/issues/255

EchterAgo commented 11 months ago

Also, the serial backend of libmodbus handles such timeouts just fine, but I'll try some more to see if i can produce such a problem.

EchterAgo commented 11 months ago

@PrplHaz4 I made another change, give it a try. I haven't actually tested this yet because I am currently changing the USB modbus driver, but I think it might work.

PrplHaz4 commented 11 months ago

@PrplHaz4 I made another change, give it a try. I haven't actually tested this yet because I am currently changing the USB modbus driver, but I think it might work.

First look the additional flush seems to be allowing it to re-connect after timeout and resume displaying values (quickly) after that - so definitely a win there. There definitely seems to be a lot of noise in the output right now - I will get some better data tonight. I know nothing about modbus - is there a really short timeout expected between messages (due to it being more of a stream than a poll) or something like that?

EchterAgo commented 11 months ago

Great. What kind of noise do you mean? I also don't know much about modbus, but the need for a delay between frames seems to be because modbus frames do not really have a uniquely identifiable start condition / preamble, so there is a need to wait a certain time to make sure there is not a message currently transferring. I got this from the APC manual and initially I sometimes hit this delay, but in the current version at least on my computer it wasn't hit.

PrplHaz4 commented 11 months ago

Great. What kind of noise do you mean? I also don't know much about modbus, but the need for a delay between frames seems to be because modbus frames do not really have a uniquely identifiable start condition / preamble, so there is a need to wait a certain time to make sure there is not a message currently transferring. I got this from the APC manual and initially I sometimes hit this delay, but in the current version at least on my computer it wasn't hit.

Here is my capture from the train this morning (with a very spotty network connection - so the noise may be related to that). You can see a lot of connection timed out, invalid data and read failed...etc.

TCP Modbus debug ``` [00][4C][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><4C><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 48.899789 [D5] send_to_all: SETINFO driver.state "quiet" 49.762261 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (0) [00][4D][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... ERROR Connection timed out: select 50.262996 _apc_modbus_read_registers: Read of 0:27 failed: Connection timed out (192.168.4.27:502) Bytes flushed (0) [00][4E][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><4D><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x4D (not 0x4E) 50.605959 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) Bytes flushed (0) [00][4F][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><4E><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0E><00><01><0E><0D><7F><00><00><0B><8B><00><00><00><2B><00><00><1E><58><00><00><1E><02><00><32><81><7D><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2D><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x4E (not 0x4F) 50.968749 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 50.968776 [D2] Communication errors: 3 50.968783 [D5] send_to_all: DATASTALE 50.968789 [D5] send_to_all: SETINFO driver.state "quiet" 51.763295 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (23) [00][50][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><50><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Bytes flushed (0) [00][51][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><51><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0E><00><01><0E><09><00><00><09><00><00><00><24><00><00><1E><58><00><00><1E><01><00><32><81><7D><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2D><00><00><00><00><00><00><00><00> 52.599061 [D5] send_to_all: SETINFO battery.runtime "19318" 52.599085 [D5] send_to_all: SETINFO battery.temperature "29.45" 52.599091 [D5] send_to_all: SETINFO ups.load "9.92" 52.599098 [D5] send_to_all: SETINFO ups.realpower "119.06" 52.599104 [D5] send_to_all: SETINFO output.current "1.12" 52.599111 [D5] send_to_all: SETINFO experimental.output.energy "3309949" 52.599117 [D5] send_to_all: SETINFO ups.efficiency "91.8" Bytes flushed (0) [00][52][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><52><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 52.925893 [D5] send_to_all: DATAOK 52.925905 [D5] send_to_all: SETINFO driver.state "quiet" 53.764182 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (0) [00][53][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><53><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Bytes flushed (0) [00][54][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><54><00><00><00><43><01><03><40><00><00><50><51><00><06><00><00><28><0E><00><01><0E><0B><00><00><0B><8B><00><00><00><2A><00><00><1E><52><00><00><1E><01><00><32><81><7D><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2D><00><00><00><00><00><00><00><00> 54.539965 [D5] send_to_all: SETINFO battery.runtime "20561" 54.539978 [D5] send_to_all: SETINFO ups.load "11.91" 54.539980 [D5] send_to_all: SETINFO ups.realpower "142.88" 54.539981 [D5] send_to_all: SETINFO ups.power "166.22" 54.539983 [D5] send_to_all: SETINFO output.current "1.31" 54.539985 [D5] send_to_all: SETINFO output.voltage "121.28" 54.539987 [D5] send_to_all: SETINFO ups.efficiency "91.5" Bytes flushed (0) [00][55][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><55><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 54.898282 [D5] send_to_all: SETINFO driver.state "quiet" 55.765124 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (0) [00][56][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><56><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Bytes flushed (0) [00][57][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><57><00><00><00><43><01><03><40><00><00><50><51><00><06><00><00><28><0E><00><01><0E><09><00><00><09><3C><00><00><00><23><00><00><1E><58><00><00><1E><01><00><32><81><7D><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2D><00><00><00><00><00><00><00><00> 56.467346 [D5] send_to_all: SETINFO ups.load "9.92" 56.467351 [D5] send_to_all: SETINFO ups.realpower "119.06" 56.467353 [D5] send_to_all: SETINFO ups.power "132.97" 56.467355 [D5] send_to_all: SETINFO output.current "1.09" 56.467358 [D5] send_to_all: SETINFO output.voltage "121.38" 56.467361 [D5] send_to_all: SETINFO ups.efficiency "91.2" Bytes flushed (0) [00][58][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... ERROR Connection timed out: select 56.968041 _apc_modbus_read_registers: Read of 1026:1033 failed: Connection timed out (192.168.4.27:502) 56.968052 [D2] Communication errors: 1 56.968056 [D5] send_to_all: DATASTALE 56.968062 [D5] send_to_all: SETINFO driver.state "quiet" 57.766267 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (23) [00][59][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... ERROR Connection timed out: select 58.267152 _apc_modbus_read_registers: Read of 0:27 failed: Connection timed out (192.168.4.27:502) Bytes flushed (0) [00][5A][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... ERROR Connection timed out: select 58.767976 _apc_modbus_read_registers: Read of 128:160 failed: Connection timed out (192.168.4.27:502) Bytes flushed (0) [00][5B][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... ERROR Connection timed out: select 59.268831 _apc_modbus_read_registers: Read of 1026:1033 failed: Connection timed out (192.168.4.27:502) 59.268840 [D2] Communication errors: 3 59.268847 [D5] send_to_all: SETINFO driver.state "quiet" 59.766884 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (0) [00][5C][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... ERROR Connection timed out: select 60.267831 _apc_modbus_read_registers: Read of 0:27 failed: Connection timed out (192.168.4.27:502) Bytes flushed (0) [00][5D][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><59><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x59 (not 0x5D) 60.548844 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) Bytes flushed (0) [00][5E][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><5A><00><00><00><43><01><03><40><00><00><50><51><00><06><00><00><28><0E><00><01><0E><0A><52><00><00><09><00><00><00><24><00><00><1E><58><00><00><1E><01><00><32><81><7D><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2D><60><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x5A (not 0x5E) 60.907371 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 60.907420 [D2] Communication errors: 3 60.907441 [D5] send_to_all: SETINFO driver.state "quiet" 61.768001 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (86) [00][5F][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><5D><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0E><00><01><0E><07><8A><00><00><0A><2D><00><00><00><26><00><00><1E><58><00><00><1E><02><00><32><81><7D><00><00><00><00><00><00><00><01><1E><52><00><00><00><00><2D><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x5D (not 0x5F) 61.995069 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) Bytes flushed (0) [00][60][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><5E><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x5E (not 0x60) 62.314687 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) Bytes flushed (0) [00][61][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><5F><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x5F (not 0x61) 62.706382 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 62.706391 [D2] Communication errors: 3 62.706399 [D5] send_to_all: SETINFO driver.state "quiet" 63.769132 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (96) [00][62][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><62><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Bytes flushed (0) [00][63][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><63><00><00><00><43><01><03><40><00><00><50><51><00><06><00><00><28><0E><00><01><0E><0A><52><00><00><09><00><00><00><25><00><00><1E><58><00><00><1E><02><00><32><81><7D><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2D><20><00><00><00><00><00><00><00><00> 64.497819 [D5] send_to_all: SETINFO ups.load "10.32" 64.497826 [D5] send_to_all: SETINFO ups.realpower "123.84" 64.497829 [D5] send_to_all: SETINFO ups.power "141.69" 64.497833 [D5] send_to_all: SETINFO output.current "1.16" 64.497837 [D5] send_to_all: SETINFO output.frequency "60.02" 64.497867 [D5] send_to_all: SETINFO ups.efficiency "90.2" Bytes flushed (0) [00][64][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><64><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 64.858010 [D5] send_to_all: DATAOK 64.858025 [D5] send_to_all: SETINFO driver.state "quiet" 65.770154 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (0) [00][65][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><65><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Bytes flushed (0) [00][66][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><66><00><00><00><43><01><03><40><00><00><50><51><00><06><00><00><28><0E><00><01><0E><0D><19><00><00><0B><49><00><00><00><29><00><00><1E><58><00><00><1E><02><00><32><81><7D><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2D><00><00><00><00><00><00><00><00><00> 66.483937 [D5] send_to_all: SETINFO battery.temperature "29.48" 66.483955 [D5] send_to_all: SETINFO ups.load "13.10" 66.483978 [D5] send_to_all: SETINFO ups.realpower "157.17" 66.483995 [D5] send_to_all: SETINFO ups.power "162.51" 66.483998 [D5] send_to_all: SETINFO output.current "1.28" 66.484028 [D5] send_to_all: SETINFO ups.efficiency "90.0" Bytes flushed (0) [00][67][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><67><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 66.881418 [D5] send_to_all: SETINFO driver.state "quiet" 67.771179 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (0) [00][68][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><68><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Bytes flushed (0) [00][69][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><69><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0E><00><01><0E><09><21><00><00><0A><84><00><00><00><27><00><00><1E><58><00><00><1E><03><00><32><81><7D><00><00><00><00><00><00><00><01><1E><52><00><00><00><00><2D><00><00><00><00><00><00><00><00> 68.487695 [D5] send_to_all: SETINFO battery.runtime "19318" 68.487706 [D5] send_to_all: SETINFO battery.voltage "54.38" 68.487712 [D5] send_to_all: SETINFO battery.temperature "29.45" 68.487715 [D5] send_to_all: SETINFO ups.load "9.13" 68.487718 [D5] send_to_all: SETINFO ups.realpower "109.55" 68.487720 [D5] send_to_all: SETINFO ups.power "151.43" 68.487722 [D5] send_to_all: SETINFO output.current "1.22" 68.487726 [D5] send_to_all: SETINFO input.voltage "121.28" 68.487748 [D5] send_to_all: SETINFO ups.efficiency "91.8" Bytes flushed (0) [00][6A][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><6A><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 68.856396 [D5] send_to_all: SETINFO driver.state "quiet" 69.772334 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (0) [00][6B][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><6B><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Bytes flushed (0) [00][6C][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><6C><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0E><00><01><0E><0C><00><00><0A><00><00><00><28><00><00><1E><58><00><00><1E><03><00><32><81><7D><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2E><00><00><00><00><00><00><00><00><00> 70.512879 [D5] send_to_all: SETINFO battery.voltage "54.50" 70.512893 [D5] send_to_all: SETINFO ups.load "12.70" 70.512898 [D5] send_to_all: SETINFO ups.realpower "152.44" 70.512901 [D5] send_to_all: SETINFO ups.power "153.84" 70.512906 [D5] send_to_all: SETINFO output.current "1.25" 70.512912 [D5] send_to_all: SETINFO input.voltage "121.38" 70.512916 [D5] send_to_all: SETINFO ups.efficiency "92.0" Bytes flushed (0) [00][6D][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><6D><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 70.886514 [D5] send_to_all: SETINFO driver.state "quiet" 71.773422 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (0) [00][6E][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><6E><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Bytes flushed (0) [00][6F][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><6F><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0E><00><01><0E><0B><1D><00><00><0A><9A><00><00><00><27><00><00><1E><58><00><00><1E><03><00><32><81><7D><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2E><00><00><00><00><00><00><00><00><00> 72.469295 [D5] send_to_all: SETINFO battery.temperature "29.48" 72.469344 [D5] send_to_all: SETINFO ups.load "11.11" 72.469379 [D5] send_to_all: SETINFO ups.realpower "133.36" 72.469386 [D5] send_to_all: SETINFO ups.power "152.66" 72.469421 [D5] send_to_all: SETINFO output.current "1.22" Bytes flushed (0) [00][70][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><70><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 72.840208 [D5] send_to_all: SETINFO driver.state "quiet" 73.774456 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (0) [00][71][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><71><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Bytes flushed (0) [00][72][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><72><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0E><00><01><0E><08><56><00><00><09><0F><00><00><00><21><00><00><1E><58><00><00><1E><03><00><32><81><7D><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2E><00><00><00><00><00><00><00><00><00> 74.517843 [D5] send_to_all: SETINFO battery.temperature "29.45" 74.517848 [D5] send_to_all: SETINFO ups.load "8.34" 74.517850 [D5] send_to_all: SETINFO ups.realpower "100.03" 74.517852 [D5] send_to_all: SETINFO ups.power "130.44" 74.517853 [D5] send_to_all: SETINFO output.current "1.03" Bytes flushed (0) [00][73][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><73><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 74.846298 [D5] send_to_all: SETINFO driver.state "quiet" 75.775479 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (0) [00][74][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><74><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Bytes flushed (0) [00][75][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><75><00><00><00><43><01><03><40><00><00><50><51><00><06><00><00><28><0E><00><01><0E><0B><1D><00><00><09><00><00><00><24><00><00><1E><58><00><00><1E><03><00><32><81><7D><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2D><00><00><00><00><00><00><00><00> 76.430593 [D5] send_to_all: SETINFO battery.runtime "20561" 76.430607 [D5] send_to_all: SETINFO ups.load "11.11" 76.430610 [D5] send_to_all: SETINFO ups.realpower "133.36" 76.430612 [D5] send_to_all: SETINFO ups.power "139.11" 76.430614 [D5] send_to_all: SETINFO output.current "1.12" 76.430618 [D5] send_to_all: SETINFO ups.efficiency "91.5" Bytes flushed (0) [00][76][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><76><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 76.778824 [D5] send_to_all: SETINFO driver.state "quiet" 77.775595 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (0) [00][77][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><77><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Bytes flushed (0) [00][78][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><78><00><00><00><43><01><03><40><00><00><50><51><00><06><00><00><28><0E><00><01><0E><0A><52><00><00><0A><58><00><00><00><27><00><00><1E><58><00><00><1E><03><00><32><81><7E><00><00><00><00><00><00><00><01><1E><52><00><00><00><00><2D><80><00><00><00><00><00><00><00><00> 78.494102 [D5] send_to_all: SETINFO ups.load "10.32" 78.494109 [D5] send_to_all: SETINFO ups.realpower "123.84" 78.494112 [D5] send_to_all: SETINFO ups.power "148.95" 78.494114 [D5] send_to_all: SETINFO output.current "1.22" 78.494118 [D5] send_to_all: SETINFO experimental.output.energy "3309950" 78.494122 [D5] send_to_all: SETINFO input.voltage "121.28" 78.494124 [D5] send_to_all: SETINFO ups.efficiency "91.0" Bytes flushed (0) [00][79][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><79><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 78.863784 [D5] send_to_all: SETINFO driver.state "quiet" 79.776654 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (0) [00][7A][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... ERROR Connection timed out: select 80.277608 _apc_modbus_read_registers: Read of 0:27 failed: Connection timed out (192.168.4.27:502) Bytes flushed (0) [00][7B][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... ERROR Connection timed out: select 80.778417 _apc_modbus_read_registers: Read of 128:160 failed: Connection timed out (192.168.4.27:502) Bytes flushed (0) [00][7C][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... ERROR Connection timed out: select 81.279267 _apc_modbus_read_registers: Read of 1026:1033 failed: Connection timed out (192.168.4.27:502) 81.279304 [D2] Communication errors: 3 81.279314 [D5] send_to_all: DATASTALE 81.279322 [D5] send_to_all: SETINFO driver.state "quiet" 81.777271 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (63) [00][7D][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... ERROR Connection timed out: select 82.278314 _apc_modbus_read_registers: Read of 0:27 failed: Connection timed out (192.168.4.27:502) Bytes flushed (0) [00][7E][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><7B><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0E><00><01><0E><09><21><00><00><0A><16><00><00><00><25><00><00><1E><58><00><00><1E><03><00><32><81><7E><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2D><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x7B (not 0x7E) 82.457998 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) Bytes flushed (0) [00][7F][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... ERROR Connection timed out: select 82.958804 _apc_modbus_read_registers: Read of 1026:1033 failed: Connection timed out (192.168.4.27:502) 82.958811 [D2] Communication errors: 3 82.958818 [D5] send_to_all: SETINFO driver.state "quiet" 83.778261 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (23) [00][80][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... ERROR Connection timed out: select 84.279311 _apc_modbus_read_registers: Read of 0:27 failed: Connection timed out (192.168.4.27:502) Bytes flushed (0) [00][81][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... ERROR Connection timed out: select 84.780036 _apc_modbus_read_registers: Read of 128:160 failed: Connection timed out (192.168.4.27:502) Bytes flushed (0) [00][82][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><7D><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x7D (not 0x82) 85.182335 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 85.182342 [D2] Communication errors: 3 85.182348 [D5] send_to_all: SETINFO driver.state "quiet" 85.778917 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (255) [00][83][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... ERROR Connection timed out: select 86.279973 _apc_modbus_read_registers: Read of 0:27 failed: Connection timed out (192.168.4.27:502) Bytes flushed (0) [00][84][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><83><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x83 (not 0x84) 86.361890 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) Bytes flushed (0) [00][85][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><84><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0E><00><01><0E><0B><00><00><09><67><00><00><00><23><00><00><1E><58><00><00><1E><02><00><32><81><7E><00><00><00><00><00><00><00><01><1E><58><00><00><00><00><2E><00><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x84 (not 0x85) 86.639099 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 86.639122 [D2] Communication errors: 3 86.639152 [D5] send_to_all: SETINFO driver.state "quiet" 87.779301 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (23) [00][86][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><86><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Bytes flushed (0) [00][87][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><87><00><00><00><43><01><03><40><00><00><50><51><00><06><00><00><28><0E><00><01><0E><0C><00><00><0C><0B><00><00><00><2C><00><00><1E><52><00><00><1E><02><00><32><81><7E><00><00><00><00><00><00><00><01><1E><52><00><00><00><00><2D><00><00><00><00><00><00><00><00> 88.547960 [D5] send_to_all: SETINFO ups.load "12.70" 88.547967 [D5] send_to_all: SETINFO ups.realpower "152.44" 88.547983 [D5] send_to_all: SETINFO ups.power "173.42" 88.547987 [D5] send_to_all: SETINFO output.current "1.38" 88.548008 [D5] send_to_all: SETINFO output.voltage "121.28" 88.548026 [D5] send_to_all: SETINFO ups.efficiency "91.5" Bytes flushed (0) [00][88][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <00><88><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> 88.913095 [D5] send_to_all: DATAOK 88.913103 [D5] send_to_all: SETINFO driver.state "quiet" 89.780424 [D5] send_to_all: SETINFO driver.state "updateinfo" Bytes flushed (0) [00][89][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <00><89><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Bytes flushed (0) [00][8A][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <00><8A><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0E><00><01><0E><0F><15><00><00><0B><00><00><00><2C><00><00><1E><4C><00><00><1E><02><00><32><81><7E><00><00><00><00><00><00><00><01><1E><4C><00><00><00><00><2D><00><00><00><00><00><00><00><00> 90.499480 [D5] send_to_all: SETINFO battery.runtime "19318" 90.499496 [D5] send_to_all: SETINFO battery.temperature "29.43" 90.499499 [D5] send_to_all: SETINFO ups.load "15.08" 90.499502 [D5] send_to_all: SETINFO ups.realpower "180.98" 90.499505 [D5] send_to_all: SETINFO ups.power "171.00" 90.499508 [D5] send_to_all: SETINFO output.voltage "121.19" 90.499512 [D5] send_to_all: SETINFO input.voltage "121.19" 90.499533 [D5] send_to_all: SETINFO ups.efficiency "91.2" Bytes flushed (0) ```
EchterAgo commented 11 months ago

Oh, you did the capture through the spotty network? That does look like what I would expect there.

I wonder if we actually need a higher timeout somewhere, it seems your connection is disconnecting when sending a command and already reconnecting before the response is received, then the response comes, sits in a buffer and gets received (now flushed) when sending the next command.

I'll have to read the modbus TCP code for this some more.

EchterAgo commented 11 months ago

I'm also not sure if this is an issue with the APC firmware or libmodbus, but I don't think it is actually a problem in nut. We could also try just waiting some time after a reconnect, before flusing.

EchterAgo commented 11 months ago

@PrplHaz4 I pushed another commit that removes the flushing before register reads, but instead adds a 1 second delay between connecting and buffer flush. If this works we should try finding a good value for the delay because 1 second is just arbitrarily chosen by me.

PrplHaz4 commented 11 months ago

@PrplHaz4 I pushed another commit that removes the flushing before register reads, but instead adds a 1 second delay between connecting and buffer flush. If this works we should try finding a good value for the delay because 1 second is just arbitrarily chosen by me.

Yes, the capture above was on a spotty network. This capture is from a stable network. It looks like the failures start 184s into the run, and continues until at least 321s without "recovering". The previous capture from the spotty network appears to have recovered after some time, and went in and out of being able to pull full values.

I'm not sure how to help on the timing of the flush - I'm sure it doesn't help providing data from two drastically different networking environments.

TCP Modbus Debug - Stable Network ``` [01][17][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><17><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0D><00><01><0E><0D><7F><00><00><0A><22><00><00><00><26><00><00><1E><38><00><00><1E><01><00><32><88><1C><00><00><00><00><00><00><00><01><1E><38><00><00><00><00><2D><00><00><00><00><00><00><00><00> 184.039766 [D5] send_to_all: SETINFO battery.temperature "29.43" 184.039771 [D5] send_to_all: SETINFO ups.load "13.50" 184.039774 [D5] send_to_all: SETINFO ups.realpower "161.95" 184.039776 [D5] send_to_all: SETINFO ups.power "145.91" 184.039778 [D5] send_to_all: SETINFO output.current "1.19" [01][18][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... ERROR Connection timed out: select 184.540478 _apc_modbus_read_registers: Read of 1026:1033 failed: Connection timed out (192.168.4.27:502) 184.540522 [D2] Communication errors: 1 184.540528 [D5] send_to_all: DATASTALE 184.540553 [D5] send_to_all: SETINFO driver.state "quiet" 185.421617 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][19][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><18><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x118 (not 0x119) 185.421733 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][1A][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><19><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x119 (not 0x11A) 185.699003 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][1B][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><1A><00><00><00><43><01><03><40><00><00><50><51><00><06><00><00><28><0D><00><01><0E><08><56><00><00><09><34><00><00><00><22><00><00><1E><38><00><00><1E><01><00><32><88><1C><00><00><00><00><00><00><00><01><1E><38><00><00><00><00><2D><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x11A (not 0x11B) 186.061582 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 186.061650 [D2] Communication errors: 3 186.061675 [D5] send_to_all: SETINFO driver.state "quiet" 187.423270 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][1C][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><1B><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x11B (not 0x11C) 187.423692 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][1D][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><1C><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x11C (not 0x11D) 187.719371 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][1E][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><1D><00><00><00><43><01><03><40><00><00><50><51><00><06><00><00><28><0D><00><01><0E><0B><83><00><00><09><89><00><00><00><23><00><00><1E><38><00><00><1E><01><00><32><88><1C><00><00><00><00><00><00><00><01><1E><38><00><00><00><00><2D><80><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x11D (not 0x11E) 188.080830 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 188.080857 [D2] Communication errors: 3 188.080878 [D5] send_to_all: SETINFO driver.state "quiet" 189.424990 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][1F][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><1E><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x11E (not 0x11F) 189.425302 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][20][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><1F><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x11F (not 0x120) 189.689561 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][21][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><20><00><00><00><43><01><03><40><00><00><50><51><00><06><00><00><28><0D><00><01><0E><0B><83><00><00><09><00><00><00><25><00><00><1E><38><00><00><1E><01><00><32><88><1C><00><00><00><00><00><00><00><01><1E><38><00><00><00><00><2D><60><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x120 (not 0x121) 190.059699 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 190.059713 [D2] Communication errors: 3 190.059725 [D5] send_to_all: SETINFO driver.state "quiet" 191.425468 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][22][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><21><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x121 (not 0x122) 191.425803 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][23][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><22><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x122 (not 0x123) 191.730711 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][24][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><23><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0D><00><01><0E><0D><19><00><00><0A><79><00><00><00><27><00><00><1E><32><00><00><1E><01><00><32><88><1C><00><00><00><00><00><00><00><01><1E><38><00><00><00><00><2D><80><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x123 (not 0x124) 192.145261 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 192.145275 [D2] Communication errors: 3 192.145288 [D5] send_to_all: SETINFO driver.state "quiet" 193.426943 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][25][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><24><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x124 (not 0x125) 193.427156 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][26][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><25><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x125 (not 0x126) 193.730254 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][27][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><26><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0D><00><01><0E><0D><19><00><00><09><00><00><00><25><00><00><1E><38><00><00><1E><01><00><32><88><1C><00><00><00><00><00><00><00><01><1E><38><00><00><00><00><2D><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x126 (not 0x127) 194.092448 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 194.092465 [D2] Communication errors: 3 194.092479 [D5] send_to_all: SETINFO driver.state "quiet" 195.428342 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][28][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><27><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x127 (not 0x128) 195.428484 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][29][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><28><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x128 (not 0x129) 195.699697 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][2A][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><29><00><00><00><43><01><03><40><00><00><50><51><00><06><00><00><28><0D><00><01><0E><0C><00><00><0B><7F><00><00><00><2B><00><00><1E><32><00><00><1E><01><00><32><88><1C><00><00><00><00><00><00><00><01><1E><32><00><00><00><00><2D><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x129 (not 0x12A) 196.060127 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 196.060139 [D2] Communication errors: 3 196.060179 [D5] send_to_all: SETINFO driver.state "quiet" 197.429938 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][2B][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><2A><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x12A (not 0x12B) 197.430144 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][2C][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><2B><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x12B (not 0x12C) 197.771843 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][2D][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><2C><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0D><00><01><0E><08><00><00><0A><79><00><00><00><27><00><00><1E><38><00><00><1E><01><00><32><88><1C><00><00><00><00><00><00><00><01><1E><38><00><00><00><00><2D><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x12C (not 0x12D) 198.181509 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 198.181525 [D2] Communication errors: 3 198.181540 [D5] send_to_all: SETINFO driver.state "quiet" 199.431254 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][2E][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><2D><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x12D (not 0x12E) 199.431427 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][2F][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><2E><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x12E (not 0x12F) 199.717634 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][30][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... <01><2F><00><00><00><43><01><03><40><00><00><4B><76><00><06><00><00><28><0D><00><01><0E><10><00><00><0B><53><00><00><00><2A><00><00><1E><32><00><00><1E><01><00><32><88><1D><00><00><00><00><00><00><00><01><1E><32><00><00><00><00><2E><00><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x12F (not 0x130) 200.060486 _apc_modbus_read_registers: Read of 1026:1033 failed: Invalid data (192.168.4.27:502) 200.060502 [D2] Communication errors: 3 200.060517 [D5] send_to_all: SETINFO driver.state "quiet" 201.433035 [D5] send_to_all: SETINFO driver.state "updateinfo" [01][31][00][00][00][06][01][03][00][00][00][1B] Waiting for a confirmation... <01><30><00><00><00><11><01><03><0E><00><7F><00><6A><00><01><00><00><00><00><00><00><00><00> Invalid transaction ID received 0x130 (not 0x131) 201.433405 _apc_modbus_read_registers: Read of 0:27 failed: Invalid data (192.168.4.27:502) [01][32][00][00][00][06][01][03][00][80][00][20] Waiting for a confirmation... <01><31><00><00><00><39><01><03><36><00><00><20><02><00><08><00><00><00><00><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><01><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><00><44><00><48><00><01><00><00> Invalid transaction ID received 0x131 (not 0x132) 201.711195 _apc_modbus_read_registers: Read of 128:160 failed: Invalid data (192.168.4.27:502) [01][33][00][00][00][06][01][03][04][02][00][07] Waiting for a confirmation... ```
EchterAgo commented 11 months ago

Thanks for testing this. Could you maybe privately (or publicly if you want) share a packet capture from Wireshark or tcpdump on port 502?

With Wireshark you can put a capture filter somewhere, just use port 502, start capturing, reproduce the problem and save the capture file.

With tcpdump you can use something like tcpdump -i <interface> -s 1500 -w apc.cap port 502 and send me the apc.cap.

p8218 commented 11 months ago

Hi, Good to see this work. If it helps, I just wanted to add that I found an APC SMT2200RMI2UC made in July 2019 didn't work with apcupsd 3.14.14 running on Windows Server 2016 via modbus over USB. modbus over serial was OK. With USB, it looked like an ordering error (responses out of order). apcupsd on Windows (2008 R2) was OK with modbus over USB with a SmartUPS 1500 LCD SMT1500I (vendor id 051d, product id 0003) made in 2015. Not with linux though, where it gave immediate errors. Also I note the new(ish) range of APC Smart-UPS's with Lithium batteries only support modbus over serial, not USB, at least in the brochures. So I wonder if working modbus over USB is restricted to older APC Smart UPS models ? Thanks.

EchterAgo commented 11 months ago

Hi, Good to see this work. If it helps, I just wanted to add that I found an APC SMT2200RMI2UC made in July 2019 didn't work with apcupsd 3.14.14 running on Windows Server 2016 via modbus over USB. modbus over serial was OK. With USB, it looked like an ordering error (responses out of order). apcupsd on Windows (2008 R2) was OK with modbus over USB with a SmartUPS 1500 LCD SMT1500I (vendor id 051d, product id 0003) made in 2015. Not with linux though, where it gave immediate errors. Also I note the new(ish) range of APC Smart-UPS's with Lithium batteries only support modbus over serial, not USB, at least in the brochures. So I wonder if working modbus over USB is restricted to older APC Smart UPS models ? Thanks.

I haven't really had experience with newer APC units, mine is from 2015. If it works with on one OS and not on the other the issue must be software.

It would be nice if you could try the code I posted in #2063, maybe we can diagnose what is going on. The implementation of this is not based on apcupsd so it might even work, in which case the bug is in apcupsd.

EchterAgo commented 11 months ago

@PrplHaz4 I think I know what the issue with TCP is and how to fix it, but I continued the discussion in #2063.