search

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

Communications with UPS lost #598

Open kosfango opened 6 years ago

kosfango commented 6 years ago

Hi All,

I have FreeBSD installed: FreeBSD server 11.1-BETA2 FreeBSD 11.1-BETA2 #0 r320065 and nut-2.7.4_8 prot port collections

I see in logs a lot of lines: [skip] Aug 22 18:47:27 server blazer_usb[77549]: Communications with UPS re-established Aug 22 18:47:27 server upsd[77551]: UPS [Ippon] data is no longer stale Aug 22 18:47:28 server upsmon[1374]: Communications with UPS ippon@localhost established Aug 22 18:47:42 server blazer_usb[77549]: Communications with UPS lost: status read failed! Aug 22 18:47:44 server upsd[77551]: Data for UPS [Ippon] is stale - check driver Aug 22 18:47:48 server upsmon[1374]: Poll UPS [ippon@localhost] failed - Data stale Aug 22 18:47:48 server upsmon[1374]: Communications with UPS ippon@localhost lost Aug 22 18:47:53 server blazer_usb[77549]: Communications with UPS re-established Aug 22 18:47:53 server upsd[77551]: UPS [Ippon] data is no longer stale Aug 22 18:47:54 server upsmon[1374]: Communications with UPS ippon@localhost established

When communication is lost:

upsc ippon@localhost

Error: Data stale

When all is fine I see next:

upsc ippon@localhost

battery.charge: 100 battery.voltage: 13.10 battery.voltage.high: 13.00 battery.voltage.low: 10.40 battery.voltage.nominal: 12.0 device.type: ups driver.name: blazer_usb driver.parameter.pollinterval: 2 driver.parameter.port: /dev/cuau1 driver.parameter.synchronous: no driver.version: 2.7.4 driver.version.internal: 0.12 input.current.nominal: 2.0 input.frequency: 49.9 input.frequency.nominal: 50 input.voltage: 225.4 input.voltage.fault: 225.8 input.voltage.nominal: 220 output.voltage: 225.8 ups.beeper.status: enabled ups.delay.shutdown: 30 ups.delay.start: 180 ups.load: 13 ups.productid: 5161 ups.status: OL ups.temperature: 25.0 ups.type: offline / line interactive ups.vendorid: 0665

but sometimes I see more shortly output:

upsc ippon@localhost

battery.voltage: 13.10 battery.voltage.high: -1.08 battery.voltage.low: -0.87 device.type: ups driver.name: blazer_usb driver.parameter.pollinterval: 2 driver.parameter.port: /dev/cuau1 driver.parameter.synchronous: no driver.version: 2.7.4 driver.version.internal: 0.12 input.frequency: 49.9 input.voltage: 227.6 input.voltage.fault: 227.6 output.voltage: 227.6 ups.beeper.status: enabled ups.delay.shutdown: 30 ups.delay.start: 180 ups.load: 14 ups.productid: 5161 ups.status: OL ups.temperature: 25.0 ups.type: offline / line interactive ups.vendorid: 0665

My configs: [ups.conf] [Ippon] driver = "blazer_usb" port = "/dev/cuau1" desc = "Ippon Back Power Pro 600"

[upsd.conf] LISTEN 127.0.0.1 LISTEN 192.168.1.1 MAXAGE 25

[upsmon.conf] RUN_AS_USER root MONITOR ippon@localhost 1 monmaster bsd master MINSUPPLIES 1 SHUTDOWNCMD "/sbin/shutdown -h +0" NOTIFYCMD "/usr/local/sbin/upssched" POLLFREQ 5 POLLFREQALERT 5 HOSTSYNC 15 DEADTIME 25 POWERDOWNFLAG /etc/killpower NOTIFYFLAG ONLINE SYSLOG+EXEC NOTIFYFLAG ONBATT SYSLOG+EXEC NOTIFYFLAG LOWBATT SYSLOG NOTIFYFLAG SHUTDOWN SYSLOG NOTIFYFLAG COMMOK SYSLOG NOTIFYFLAG COMMBAD SYSLOG RBWARNTIME 43200 NOCOMMWARNTIME 300 FINALDELAY 10

Any ideas?

Debug output:

/usr/local/libexec/nut/blazer_usb -a Ippon -DDDDD

Network UPS Tools - Megatec/Q1 protocol USB driver 0.12 (2.7.4) 0.000000 debug level is '5' 0.002693 Checking device (0A12/0001) (/dev/usb//dev/ugen2.2) 0.002773 - VendorID: 0a12 0.002782 - ProductID: 0001 0.002787 - Manufacturer: unknown 0.002791 - Product: unknown 0.002796 - Serial Number: unknown 0.002800 - Bus: /dev/usb 0.002805 - Device release number: 1958 0.002809 Trying to match device 0.002816 Device does not match - skipping 0.002835 Checking device (0665/5161) (/dev/usb//dev/ugen3.2) 0.034716 - VendorID: 0665 0.034739 - ProductID: 5161 0.034747 - Manufacturer: Cypress Semiconductor 0.034754 - Product: USB to Serial 0.034760 - Serial Number: unknown 0.034767 - Bus: /dev/usb 0.034773 - Device release number: 0002 0.034780 Trying to match device 0.034789 Device matches 0.034806 nut_usb_set_altinterface: skipped usb_set_altinterface(udev, 0) 0.034831 send_to_all: SETINFO ups.vendorid "0665" 0.034842 send_to_all: SETINFO ups.productid "5161" 0.034855 send_to_all: SETINFO device.type "ups" 0.034866 send_to_all: SETINFO driver.version "2.7.4" 0.034882 send_to_all: SETINFO driver.version.internal "0.12" 0.034889 send_to_all: SETINFO driver.name "blazer_usb" 0.034896 Trying megatec protocol... 0.037703 send: Q1 1.018114 read: Unknown error 1.018142 blazer_status: short reply 1.018151 Status read 1 failed 1.020668 send: Q1 2.001112 read: Unknown error 2.001140 blazer_status: short reply 2.001149 Status read 2 failed 2.003632 send: Q1 3.076105 read: Unknown error 3.076137 blazer_status: short reply 3.076144 Status read 3 failed 3.076149 Trying mustek protocol... 3.078595 send: QS 4.059094 read: Unknown error 4.059121 blazer_status: short reply 4.059130 Status read 1 failed 4.061558 send: QS 5.252095 read: Unknown error 5.252122 blazer_status: short reply 5.252132 Status read 2 failed 5.254514 send: QS 6.436093 read: Unknown error 6.436118 blazer_status: short reply 6.436128 Status read 3 failed 6.436135 Trying megatec/old protocol... 6.438471 send: D 7.419094 read: Unknown error 7.419115 blazer_status: short reply 7.419122 Status read 1 failed 7.421446 send: D 8.580106 read: Unknown error 8.580128 blazer_status: short reply 8.580134 Status read 2 failed 8.582399 send: D 9.764098 read: Unknown error 9.764126 blazer_status: short reply 9.764135 Status read 3 failed 9.764143 Trying zinto protocol... 9.766355 send: Q1 10.747101 read: Unknown error 10.747128 blazer_status: short reply 10.747137 Status read 1 failed 10.749316 send: Q1 11.940097 read: Unknown error 11.940124 blazer_status: short reply 11.940134 Status read 2 failed 11.942271 send: Q1 12.303283 read: (222.3 222.3 221.8 013 50.1 13.1 25.0 00001001 12.303331 send_to_all: SETINFO input.voltage "222.3" 12.303344 send_to_all: SETINFO input.voltage.fault "222.3" 12.303353 send_to_all: SETINFO output.voltage "221.8" 12.303367 send_to_all: SETINFO ups.load "13" 12.303376 send_to_all: SETINFO input.frequency "50.1" 12.303386 send_to_all: SETINFO battery.voltage "13.10" 12.303394 send_to_all: SETINFO ups.temperature "25.0" 12.303402 send_to_all: SETINFO ups.beeper.status "enabled" 12.303410 send_to_all: SETINFO ups.type "offline / line interactive" 12.303421 send_to_all: SETINFO ups.status "OL" 12.303427 Status read in 3 tries 12.303432 Supported UPS detected with zinto protocol 12.306264 send: F 12.495293 read: D01001 12.495317 blazer_rating: short reply 12.495324 Rating read 1 failed 12.498251 send: F 13.479097 read: Unknown error 13.479124 blazer_rating: short reply 13.479133 Rating read 2 failed 13.481218 send: F 13.679249 read: F F001 13.679272 blazer_rating: short reply 13.679278 Rating read 3 failed 13.679284 Rating information unavailable 13.682215 send: FW? 14.663097 read: Unknown error 14.663124 blazer_vendor: short reply 14.663132 Vendor information read 1 failed 14.666174 send: FW? 15.844096 read: Unknown error 15.844117 blazer_vendor: short reply 15.844123 Vendor information read 2 failed 15.847134 send: FW? 16.828101 read: Unknown error 16.828129 blazer_vendor: short reply 16.828138 Vendor information read 3 failed 16.828145 Vendor information unavailable 16.828152 No values provided for battery high/low voltages in ups.conf

16.828170 send_to_all: SETINFO battery.voltage.low "-0.87" 16.828186 send_to_all: SETINFO battery.voltage.high "-1.08" 16.828195 Using 'guestimation' (low: -0.866667, high: -1.083333)! 16.828204 Battery runtime will not be calculated (runtimecal not set) 16.828216 send_to_all: SETINFO ups.delay.start "180" 16.828230 send_to_all: SETINFO ups.delay.shutdown "30" 16.828245 send_to_all: ADDCMD beeper.toggle 16.828251 send_to_all: ADDCMD load.off 16.828257 send_to_all: ADDCMD load.on 16.828263 send_to_all: ADDCMD shutdown.return 16.828269 send_to_all: ADDCMD shutdown.stayoff 16.828276 send_to_all: ADDCMD shutdown.stop 16.828281 send_to_all: ADDCMD test.battery.start 16.828288 send_to_all: ADDCMD test.battery.start.deep 16.828294 send_to_all: ADDCMD test.battery.start.quick 16.828301 send_to_all: ADDCMD test.battery.stop 16.831096 send: Q1 18.020092 read: Unknown error 18.020119 blazer_status: short reply 18.020128 Communications with UPS lost: status read failed! 18.020506 dstate_init: sock /var/db/nut/blazer_usb-Ippon open on fd 6 18.020522 send_to_all: SETINFO driver.parameter.pollinterval "15" 18.020534 send_to_all: SETINFO driver.parameter.synchronous "no" 18.023059 send: Q1 19.004111 read: Unknown error 19.004139 blazer_status: short reply 19.004147 Communications with UPS lost: status read failed! 33.024511 send: Q1 34.005091 read: Unknown error 34.005118 blazer_status: short reply 34.005126 Communications with UPS lost: status read failed! 48.025971 send: Q1 49.090098 read: Unknown error 49.090126 blazer_status: short reply 49.090135 Communications with UPS lost: status read failed! 63.026430 send: Q1 63.373436 read: (222.3 222.3 222.3 013 50.1 13.1 25.0 00001001 63.373480 send_to_all: SETINFO output.voltage "222.3" 63.373513 Communications with UPS re-established 63.373525 send_to_all: DATAOK 78.029885 send: Q1 79.010087 read: Unknown error 79.010115 blazer_status: short reply 79.010123 Communications with UPS lost: status read failed! 93.030339 send: Q1 93.228361 read: Q0 Q11 93.228389 blazer_status: short reply 93.228397 Communications with UPS lost: status read failed! 108.032799 send: Q1 109.013082 read: Unknown error 109.013109 blazer_status: short reply 109.013117 Communications with UPS lost: status read failed! 123.033254 send: Q1 123.243274 read: Q1 P11 123.243297 blazer_status: short reply 123.243303 Communications with UPS lost: status read failed! 138.034713 send: Q1 139.015084 read: Unknown error 139.015111 blazer_status: short reply 139.015122 send_to_all: DATASTALE 153.036169 send: Q1 154.017143 read: Unknown error 154.017166 blazer_status: short reply 168.037627 send: Q1 169.018096 read: Unknown error 169.018126 blazer_status: short reply

Thanks

zykh commented 6 years ago

but sometimes I see more shortly output:

That's because, on startup, the driver can't always get a reply to the F<cr> megatec query from the device.

Debug output:

Can you post also the output without altering the default pollinterval / -i option?

Any ideas?

hmm... a possible source of problems could be that you're on FreeBSD with its libusb 0.1 (which doesn't return -errno on error like real libusb 0.1, and as the driver expects, but almost always -1), and using NUT with this, wrong, patch (which further distances the driver from a chance to get the real error), and if the driver can't identify the real error happened while reading, it can't react properly. If possible, try the driver compiled (without patches) from this branch: https://github.com/networkupstools/nut/tree/libusb-compat-1.0

I would also give a chance to the other USB subdrivers (you're currently using the cypress one), starting from the phoenix one (again, it will not work exactly as expected because of the aforementioned FreeBSD's libusb 0.1/wrong patch combo, but, nonetheless, it should perform an interrupt read -which should fail- before sending the command to the device, and this could have some, maybe positive, effects).

Also, while it should not make a great difference, consider trying the nutdrv_qx driver.

kosfango commented 6 years ago

Can you post also the output without altering the default pollinterval / -i option?

Thank you for reply. I did new tests as you recommended:

/usr/local/libexec/nut/blazer_usb -a Ippon -DDD Network UPS Tools - Megatec/Q1 protocol USB driver 0.12 (2.7.4) 0.000000 debug level is '3' 0.002744 Checking device (0A12/0001) (/dev/usb//dev/ugen2.2) 0.002856 - VendorID: 0a12 0.002865 - ProductID: 0001 0.002871 - Manufacturer: unknown 0.002876 - Product: unknown 0.002892 - Serial Number: unknown 0.002902 - Bus: /dev/usb 0.002907 - Device release number: 1958 0.002911 Trying to match device 0.002922 Device does not match - skipping 0.002945 Checking device (0665/5161) (/dev/usb//dev/ugen3.2) 0.034945 - VendorID: 0665 0.034965 - ProductID: 5161 0.034972 - Manufacturer: Cypress Semiconductor 0.034979 - Product: USB to Serial 0.034985 - Serial Number: unknown 0.034992 - Bus: /dev/usb 0.034999 - Device release number: 0002 0.035005 Trying to match device 0.035024 Device matches 0.035045 nut_usb_set_altinterface: skipped usb_set_altinterface(udev, 0) 0.035083 Trying megatec protocol... 0.037947 send: Q1 0.406942 read: (229.4 229.4 229.4 013 49.9 13.1 25.0 00001001 0.407040 Status read in 1 tries 0.407049 Supported UPS detected with megatec protocol 0.409927 send: F 0.598929 read: #220.0 002 12.00 50.0 0.598979 Ratings read in 1 tries 0.601918 send: I 1.582867 read: Unknown error 1.582894 blazer_vendor: short reply 1.582902 Vendor information read 1 failed 1.585889 send: I 2.566860 read: Unknown error 2.566887 blazer_vendor: short reply 2.566896 Vendor information read 2 failed 2.569851 send: I 3.550866 read: Unknown error 3.550893 blazer_vendor: short reply 3.550901 Vendor information read 3 failed 3.550908 Vendor information unavailable 3.550915 No values provided for battery high/low voltages in ups.conf

3.550939 Using 'guestimation' (low: 10.400000, high: 13.000000)! 3.550951 Battery runtime will not be calculated (runtimecal not set) 3.553837 send: Q1 4.619863 read: Unknown error 4.619888 blazer_status: short reply 4.619897 Communications with UPS lost: status read failed! 4.620281 dstate_init: sock /var/db/nut/blazer_usb-Ippon open on fd 6 4.622781 send: Q1 5.603881 read: Unknown error 5.603908 blazer_status: short reply 5.603922 Communications with UPS lost: status read failed! 6.625708 send: Q1 7.605867 read: Unknown error 7.605895 blazer_status: short reply 7.605903 Communications with UPS lost: status read failed! 8.626637 send: Q1 9.606860 read: Unknown error 9.606885 blazer_status: short reply 9.606895 Communications with UPS lost: status read failed! 10.627572 send: Q1 11.607863 read: Unknown error 11.607890 blazer_status: short reply 12.631494 send: Q1 13.866860 read: Unknown error 13.866886 blazer_status: short reply 14.632421 send: Q1 15.818862 read: Unknown error 15.818890 blazer_status: short reply 16.634350 send: Q1 17.614859 read: Unknown error 17.614886 blazer_status: short reply 18.635279 send: Q1 19.818860 read: Unknown error 19.818889 blazer_status: short reply 20.636207 send: Q1 20.982203 read: (231.1 230.7 230.7 013 49.9 13.1 25.0 00001001 20.982277 Communications with UPS re-established 22.641136 send: Q1 22.838143 read: Q01001 22.838167 blazer_status: short reply 22.838176 Communications with UPS lost: status read failed! 24.646064 send: Q1 25.626861 read: Unknown error 25.626888 blazer_status: short reply 25.626896 Communications with UPS lost: status read failed! 26.646991 send: Q1 27.627861 read: Unknown error 27.627886 blazer_status: short reply 27.627894 Communications with UPS lost: status read failed! 28.647920 send: Q1 29.628869 read: Unknown error 29.628895 blazer_status: short reply 29.628904 Communications with UPS lost: status read failed! 30.651849 send: Q1 31.632865 read: Unknown error 31.632891 blazer_status: short reply 32.653777 send: Q1 33.897856 read: Unknown error 33.897882 blazer_status: short reply 34.654726 send: Q1 34.997698 read: (230.7 230.7 230.7 013 50.1 13.1 25.0 00001001 34.997769 Communications with UPS re-established 36.656633 send: Q1 37.636885 read: Unknown error 37.636910 blazer_status: short reply 37.636916 Communications with UPS lost: status read failed! 38.661560 send: Q1 39.641860 read: Unknown error 39.641887 blazer_status: short reply 39.641896 Communications with UPS lost: status read failed! 40.662488 send: Q1 41.737863 read: Unknown error 41.737887 blazer_status: short reply 41.737895 Communications with UPS lost: status read failed! 42.663417 send: Q1 ^C

and

/usr/local/libexec/nut/blazer_usb -a Ippon -DDD -i 15 Network UPS Tools - Megatec/Q1 protocol USB driver 0.12 (2.7.4) 0.000000 debug level is '3' 0.002604 Checking device (0A12/0001) (/dev/usb//dev/ugen2.2) 0.002683 - VendorID: 0a12 0.002716 - ProductID: 0001 0.002723 - Manufacturer: unknown 0.002727 - Product: unknown 0.002732 - Serial Number: unknown 0.002736 - Bus: /dev/usb 0.002741 - Device release number: 1958 0.002746 Trying to match device 0.002756 Device does not match - skipping 0.002779 Checking device (0665/5161) (/dev/usb//dev/ugen3.2) 0.034010 - VendorID: 0665 0.034032 - ProductID: 5161 0.034037 - Manufacturer: Cypress Semiconductor 0.034043 - Product: USB to Serial 0.034048 - Serial Number: unknown 0.034052 - Bus: /dev/usb 0.034057 - Device release number: 0002 0.034061 Trying to match device 0.034078 Device matches 0.034096 nut_usb_set_altinterface: skipped usb_set_altinterface(udev, 0) 0.034125 Trying megatec protocol... 0.037011 send: Q1 0.385031 read: (228.5 228.9 228.5 015 49.9 13.1 25.0 00001001 0.385121 Status read in 1 tries 0.385130 Supported UPS detected with megatec protocol 0.388007 send: F 1.368757 read: Unknown error 1.368787 blazer_rating: short reply 1.368795 Rating read 1 failed 1.370961 send: F 1.568981 read: F F001 1.569009 blazer_rating: short reply 1.569018 Rating read 2 failed 1.571945 send: F 2.552746 read: Unknown error 2.552773 blazer_rating: short reply 2.552782 Rating read 3 failed 2.552789 Rating information unavailable 2.554915 send: I 2.752932 read: F H001 2.752952 blazer_vendor: short reply 2.752958 Vendor information read 1 failed 2.755904 send: I 3.736759 read: Unknown error 3.736787 blazer_vendor: short reply 3.736796 Vendor information read 2 failed 3.738870 send: I 3.936890 read: I H001 3.936914 blazer_vendor: short reply 3.936922 Vendor information read 3 failed 3.936929 Vendor information unavailable 3.936936 No values provided for battery high/low voltages in ups.conf

3.936958 Using 'guestimation' (low: -0.866667, high: -1.083333)! 3.936971 Battery runtime will not be calculated (runtimecal not set) 3.939862 send: Q1 4.128880 read: P1H001 4.128905 blazer_status: short reply 4.128912 Communications with UPS lost: status read failed! 4.129307 dstate_init: sock /var/db/nut/blazer_usb-Ippon open on fd 6 4.131857 send: Q1 5.112745 read: Unknown error 5.112773 blazer_status: short reply 5.112781 Communications with UPS lost: status read failed! 19.133332 send: Q1 20.113745 read: Unknown error 20.113771 blazer_status: short reply 20.113780 Communications with UPS lost: status read failed! 34.133785 send: Q1 35.114745 read: Unknown error 35.114772 blazer_status: short reply 35.114781 Communications with UPS lost: status read failed! 49.139339 send: Q1 50.355747 read: Unknown error 50.355774 blazer_status: short reply ^C

kosfango commented 6 years ago

hmm... a possible source of problems could be that you're on FreeBSD with its libusb 0.1

I forgot to get more helpful info:

  1. Many year ago all worked fine. However, about 2 years ago it broken. Sometimes it worked fine, sometimes I had "error data stale", but a couple weeks ago NUT lost my UPS forever. I used com port cable to connect my UPS. Probably the cable has become unusable, so I changed com to usb and reconfigured NUT, but I gotten the same issue.

  2. I have another server with FreeBSD Stable+NUT+new Ippon with LCD like 600 back power office. After a few hours system lost UPS (OS doesn't see UPS device) until re-plug usb cable. Reboot doesn't have effect. I used usbhid-ups driver.

Analyzing both cases, I suspect that maybe something is broken in the OS itself

kosfango commented 6 years ago

If possible, try the driver compiled (without patches) from this branch: https://github.com/networkupstools/nut/tree/libusb-compat-1.0

I did git clone -b libusb-compat-1.0, then ./autogen.sh && ./configure --prefix=/opt/nut && make && make install, then I created symlink to nut.conf and tried to start...The same issue...

kosfango commented 6 years ago

I would also give a chance to the other USB subdrivers (you're currently using the cypress one), starting from the phoenix

Tried...The same issue

kosfango commented 6 years ago

I did git clone -b libusb-compat-1.0, then ./autogen.sh && ./configure --prefix=/opt/nut && make && make install, then I created symlink to nut.conf and tried to start...The same issue...

/opt/nut/bin/blazer_usb -DDD -a Ippon

Network UPS Tools - Megatec/Q1 protocol USB driver 0.17 (2.7.4-605-g10d40386) 0.000000 [D1] debug level is '3' 0.002161 [D2] nut_libusb_open: checking device 1 of 8. 0.002289 [D2] nut_libusb_open: - VendorID: 0000. 0.002299 [D2] nut_libusb_open: - ProductID: 0000. 0.002305 [D2] nut_libusb_open: - Manufacturer: Intel. 0.002311 [D2] nut_libusb_open: - Product: EHCI root HUB. 0.002316 [D2] nut_libusb_open: - Serial Number: unknown. 0.002325 [D2] nut_libusb_open: - Bus: 004. 0.002331 [D2] nut_libusb_open: - Device release number: 0100. 0.002336 [D2] nut_libusb_open: trying to match device... 0.002357 [D2] nut_libusb_open: device does not match - skipping. 0.002393 [D2] nut_libusb_open: checking device 2 of 8. 0.002463 [D2] nut_libusb_open: - VendorID: 0000. 0.002484 [D2] nut_libusb_open: - ProductID: 0000. 0.002491 [D2] nut_libusb_open: - Manufacturer: Intel. 0.002496 [D2] nut_libusb_open: - Product: UHCI root HUB. 0.002505 [D2] nut_libusb_open: - Serial Number: unknown. 0.002510 [D2] nut_libusb_open: - Bus: 003. 0.002516 [D2] nut_libusb_open: - Device release number: 0100. 0.002521 [D2] nut_libusb_open: trying to match device... 0.002529 [D2] nut_libusb_open: device does not match - skipping. 0.002549 [D2] nut_libusb_open: checking device 3 of 8. 0.002614 [D2] nut_libusb_open: - VendorID: 0000. 0.002623 [D2] nut_libusb_open: - ProductID: 0000. 0.002629 [D2] nut_libusb_open: - Manufacturer: Intel. 0.002645 [D2] nut_libusb_open: - Product: UHCI root HUB. 0.002652 [D2] nut_libusb_open: - Serial Number: unknown. 0.002657 [D2] nut_libusb_open: - Bus: 001. 0.002663 [D2] nut_libusb_open: - Device release number: 0100. 0.002668 [D2] nut_libusb_open: trying to match device... 0.002675 [D2] nut_libusb_open: device does not match - skipping. 0.002696 [D2] nut_libusb_open: checking device 4 of 8. 0.002760 [D2] nut_libusb_open: - VendorID: 0000. 0.002769 [D2] nut_libusb_open: - ProductID: 0000. 0.002775 [D2] nut_libusb_open: - Manufacturer: Intel. 0.002791 [D2] nut_libusb_open: - Product: UHCI root HUB. 0.002797 [D2] nut_libusb_open: - Serial Number: unknown. 0.002803 [D2] nut_libusb_open: - Bus: 002. 0.002808 [D2] nut_libusb_open: - Device release number: 0100. 0.002814 [D2] nut_libusb_open: trying to match device... 0.002821 [D2] nut_libusb_open: device does not match - skipping. 0.002841 [D2] nut_libusb_open: checking device 5 of 8. 0.002908 [D2] nut_libusb_open: - VendorID: 0000. 0.002918 [D2] nut_libusb_open: - ProductID: 0000. 0.002932 [D2] nut_libusb_open: - Manufacturer: Intel. 0.002938 [D2] nut_libusb_open: - Product: UHCI root HUB. 0.002944 [D2] nut_libusb_open: - Serial Number: unknown. 0.002950 [D2] nut_libusb_open: - Bus: 000. 0.002955 [D2] nut_libusb_open: - Device release number: 0100. 0.002963 [D2] nut_libusb_open: trying to match device... 0.002971 [D2] nut_libusb_open: device does not match - skipping. 0.002991 [D2] nut_libusb_open: checking device 6 of 8. 0.018350 [D2] nut_libusb_open: - VendorID: 12d1. 0.018390 [D2] nut_libusb_open: - ProductID: 1001. 0.018398 [D2] nut_libusb_open: - Manufacturer: HUAWEI Technology. 0.018407 [D2] nut_libusb_open: - Product: HUAWEI Mobile. 0.018415 [D2] nut_libusb_open: - Serial Number: unknown. 0.018423 [D2] nut_libusb_open: - Bus: 004. 0.018431 [D2] nut_libusb_open: - Device release number: 0000. 0.018444 [D2] nut_libusb_open: trying to match device... 0.018456 [D2] nut_libusb_open: device does not match - skipping. 0.018496 [D2] nut_libusb_open: checking device 7 of 8. 0.050397 [D2] nut_libusb_open: - VendorID: 0665. 0.050419 [D2] nut_libusb_open: - ProductID: 5161. 0.050428 [D2] nut_libusb_open: - Manufacturer: Cypress Semiconductor. 0.050437 [D2] nut_libusb_open: - Product: USB to Serial. 0.050445 [D2] nut_libusb_open: - Serial Number: unknown. 0.050453 [D2] nut_libusb_open: - Bus: 003. 0.050461 [D2] nut_libusb_open: - Device release number: 0002. 0.050476 [D2] nut_libusb_open: trying to match device... 0.050496 [D2] nut_libusb_open: device matches. 0.050521 [D3] nut_usb_claim_interface: libusb_kernel_driver_active() returned 0 (no driver active). 0.050535 [D2] nut_libusb_open: claimed interface 0 successfully. 0.050546 [D3] nut_usb_set_altinterface: skipped libusb_set_interface_alt_setting(udev, 0, 0). 0.050587 [D2] Trying megatec protocol... 1.031447 [D3] flush: Timeout 1.034356 [D3] send: Q1 2.220433 [D3] read: Timeout 2.220460 [D2] blazer_status: short reply 2.220470 [D2] Status read 1 failed 3.201435 [D3] flush: Timeout 3.204274 [D3] send: Q1 4.184454 [D3] read: Timeout 4.184480 [D2] blazer_status: short reply 4.184487 [D2] Status read 2 failed 5.165422 [D3] flush: Timeout 5.168204 [D3] send: Q1 6.347444 [D3] read: Timeout 6.347471 [D2] blazer_status: short reply 6.347481 [D2] Status read 3 failed 6.347489 [D2] Trying mustek protocol... 7.328421 [D3] flush: Timeout 7.331126 [D3] send: QS 8.491437 [D3] read: Timeout 8.491465 [D2] blazer_status: short reply 8.491475 [D2] Status read 1 failed 9.472420 [D3] flush: Timeout 9.475050 [D3] send: QS 10.635443 [D3] read: Timeout 10.635471 [D2] blazer_status: short reply 10.635481 [D2] Status read 2 failed 11.616441 [D3] flush: Timeout 11.618972 [D3] send: QS 12.779421 [D3] read: Timeout 12.779449 [D2] blazer_status: short reply 12.779459 [D2] Status read 3 failed 12.779467 [D2] Trying megatec/old protocol... 13.760421 [D3] flush: Timeout 13.762900 [D3] send: D 14.743416 [D3] read: Timeout 14.743438 [D2] blazer_status: short reply 14.743445 [D2] Status read 1 failed 15.724418 [D3] flush: Timeout 15.726829 [D3] send: D 16.707440 [D3] read: Timeout 16.707468 [D2] blazer_status: short reply 16.707478 [D2] Status read 2 failed 17.688423 [D3] flush: Timeout 17.690758 [D3] send: D 18.671437 [D3] read: Timeout 18.671467 [D2] blazer_status: short reply 18.671476 [D2] Status read 3 failed 18.671485 [D2] Trying zinto protocol... 19.652433 [D3] flush: Timeout 19.654690 [D3] send: Q1 20.715438 [D3] read: Timeout 20.715465 [D2] blazer_status: short reply 20.715475 [D2] Status read 1 failed 21.696458 [D3] flush: Timeout 21.698623 [D3] send: Q1 22.679429 [D3] read: Timeout 22.679457 [D2] blazer_status: short reply 22.679467 [D2] Status read 2 failed 23.660423 [D3] flush: Timeout 23.662548 [D3] send: Q1 24.843423 [D3] read: Timeout 24.843450 [D2] blazer_status: short reply 24.843460 [D2] Status read 3 failed 24.843467 No supported UPS detected

kosfango commented 6 years ago

One of successfuly attempts:

/opt/nut/bin/blazer_usb -DDD -a Ippon Network UPS Tools - Megatec/Q1 protocol USB driver 0.17 (2.7.4-605-g10d40386) 0.000000 [D1] debug level is '3' 0.002521 [D2] nut_libusb_open: checking device 1 of 8. 0.002669 [D2] nut_libusb_open: - VendorID: 0000. 0.002682 [D2] nut_libusb_open: - ProductID: 0000. 0.002690 [D2] nut_libusb_open: - Manufacturer: Intel. 0.002698 [D2] nut_libusb_open: - Product: UHCI root HUB. 0.002705 [D2] nut_libusb_open: - Serial Number: unknown. 0.002713 [D2] nut_libusb_open: - Bus: 003. 0.002720 [D2] nut_libusb_open: - Device release number: 0100. 0.002728 [D2] nut_libusb_open: trying to match device... 0.002741 [D2] nut_libusb_open: device does not match - skipping. 0.002772 [D2] nut_libusb_open: checking device 2 of 8. 0.002870 [D2] nut_libusb_open: - VendorID: 0000. 0.002882 [D2] nut_libusb_open: - ProductID: 0000. 0.002890 [D2] nut_libusb_open: - Manufacturer: Intel. 0.002898 [D2] nut_libusb_open: - Product: UHCI root HUB. 0.002905 [D2] nut_libusb_open: - Serial Number: unknown. 0.002913 [D2] nut_libusb_open: - Bus: 000. 0.002920 [D2] nut_libusb_open: - Device release number: 0100. 0.002928 [D2] nut_libusb_open: trying to match device... 0.002937 [D2] nut_libusb_open: device does not match - skipping. 0.002963 [D2] nut_libusb_open: checking device 3 of 8. 0.003040 [D2] nut_libusb_open: - VendorID: 0000. 0.003052 [D2] nut_libusb_open: - ProductID: 0000. 0.003060 [D2] nut_libusb_open: - Manufacturer: Intel. 0.003068 [D2] nut_libusb_open: - Product: EHCI root HUB. 0.003076 [D2] nut_libusb_open: - Serial Number: unknown. 0.003083 [D2] nut_libusb_open: - Bus: 004. 0.003091 [D2] nut_libusb_open: - Device release number: 0100. 0.003098 [D2] nut_libusb_open: trying to match device... 0.003107 [D2] nut_libusb_open: device does not match - skipping. 0.003131 [D2] nut_libusb_open: checking device 4 of 8. 0.003206 [D2] nut_libusb_open: - VendorID: 0000. 0.003217 [D2] nut_libusb_open: - ProductID: 0000. 0.003225 [D2] nut_libusb_open: - Manufacturer: Intel. 0.003233 [D2] nut_libusb_open: - Product: UHCI root HUB. 0.003240 [D2] nut_libusb_open: - Serial Number: unknown. 0.003248 [D2] nut_libusb_open: - Bus: 002. 0.003255 [D2] nut_libusb_open: - Device release number: 0100. 0.003263 [D2] nut_libusb_open: trying to match device... 0.003271 [D2] nut_libusb_open: device does not match - skipping. 0.003296 [D2] nut_libusb_open: checking device 5 of 8. 0.003371 [D2] nut_libusb_open: - VendorID: 0000. 0.003382 [D2] nut_libusb_open: - ProductID: 0000. 0.003390 [D2] nut_libusb_open: - Manufacturer: Intel. 0.003397 [D2] nut_libusb_open: - Product: UHCI root HUB. 0.003405 [D2] nut_libusb_open: - Serial Number: unknown. 0.003413 [D2] nut_libusb_open: - Bus: 001. 0.003420 [D2] nut_libusb_open: - Device release number: 0100. 0.003427 [D2] nut_libusb_open: trying to match device... 0.003436 [D2] nut_libusb_open: device does not match - skipping. 0.003461 [D2] nut_libusb_open: checking device 6 of 8. 0.018818 [D2] nut_libusb_open: - VendorID: 12d1. 0.018840 [D2] nut_libusb_open: - ProductID: 1001. 0.018850 [D2] nut_libusb_open: - Manufacturer: HUAWEI Technology. 0.018858 [D2] nut_libusb_open: - Product: HUAWEI Mobile. 0.018865 [D2] nut_libusb_open: - Serial Number: unknown. 0.018873 [D2] nut_libusb_open: - Bus: 004. 0.018881 [D2] nut_libusb_open: - Device release number: 0000. 0.018889 [D2] nut_libusb_open: trying to match device... 0.018900 [D2] nut_libusb_open: device does not match - skipping. 0.018940 [D2] nut_libusb_open: checking device 7 of 8. 0.050470 [D2] nut_libusb_open: - VendorID: 0665. 0.050499 [D2] nut_libusb_open: - ProductID: 5161. 0.050510 [D2] nut_libusb_open: - Manufacturer: Cypress Semiconductor. 0.050524 [D2] nut_libusb_open: - Product: USB to Serial. 0.050535 [D2] nut_libusb_open: - Serial Number: unknown. 0.050546 [D2] nut_libusb_open: - Bus: 003. 0.050557 [D2] nut_libusb_open: - Device release number: 0002. 0.050568 [D2] nut_libusb_open: trying to match device... 0.050593 [D2] nut_libusb_open: device matches. 0.050624 [D3] nut_usb_claim_interface: libusb_kernel_driver_active() returned 0 (no driver active). 0.050645 [D2] nut_libusb_open: claimed interface 0 successfully. 0.050656 [D3] nut_usb_set_altinterface: skipped libusb_set_interface_alt_setting(udev, 0, 0). 0.050693 [D2] Trying megatec protocol... 1.031930 [D3] flush: Timeout 1.034432 [D3] send: Q1 2.014917 [D3] read: Timeout 2.014950 [D2] blazer_status: short reply 2.014963 [D2] Status read 1 failed 2.995922 [D3] flush: Timeout 2.998357 [D3] send: Q1 4.230913 [D3] read: Timeout 4.230945 [D2] blazer_status: short reply 4.230958 [D2] Status read 2 failed 5.211909 [D3] flush: Timeout 5.214290 [D3] send: Q1 5.554310 [D3] read: (227.6 227.2 227.6 014 49.9 13.1 25.0 00001001 5.554423 [D2] Status read in 3 tries 5.554435 Supported UPS detected with megatec protocol 6.534916 [D3] flush: Timeout 6.537227 [D3] send: F 7.517908 [D3] read: Timeout 7.517939 [D2] blazer_rating: short reply 7.517952 [D1] Rating read 1 failed 8.498915 [D3] flush: Timeout 8.501158 [D3] send: F 9.481914 [D3] read: Timeout 9.481947 [D2] blazer_rating: short reply 9.481961 [D1] Rating read 2 failed 10.462912 [D3] flush: Timeout 10.465088 [D3] send: F 10.674134 [D3] read: D F D1 10.674166 [D2] blazer_rating: short reply 10.674179 [D1] Rating read 3 failed 10.674189 Rating information unavailable 11.654910 [D3] flush: Timeout 11.657048 [D3] send: I 12.637917 [D3] read: Timeout 12.637949 [D2] blazer_vendor: short reply 12.637962 [D1] Vendor information read 1 failed 13.618918 [D3] flush: Timeout 13.621981 [D3] send: I 14.602914 [D3] read: Timeout 14.602946 [D2] blazer_vendor: short reply 14.602959 [D1] Vendor information read 2 failed 15.583924 [D3] flush: Timeout 15.586904 [D3] send: I 16.567920 [D3] read: Timeout 16.567946 [D2] blazer_vendor: short reply 16.567955 [D1] Vendor information read 3 failed 16.567962 Vendor information unavailable 16.567969 No values provided for battery high/low voltages in ups.conf

16.567993 Using 'guestimation' (low: -0.866667, high: -1.083333)! 16.568001 Battery runtime will not be calculated (runtimecal not set) 17.548918 [D3] flush: Timeout 17.551834 [D3] send: Q1 18.598909 [D3] read: Timeout 18.598941 [D2] blazer_status: short reply 18.598954 [D1] Communications with UPS lost: status read failed! 18.679899 [D2] dstate_init: sock /var/state/ups/blazer_usb-Ippon open on fd 8 19.660909 [D3] flush: Timeout 19.663765 [D3] send: Q1 20.017786 [D3] read: (229.4 229.4 229.8 015 49.9 13.1 25.0 00001001 21.663918 [D3] flush: Timeout 21.666686 [D3] send: Q1 22.646909 [D3] read: Timeout 22.646940 [D2] blazer_status: short reply 22.646953 [D1] Communications with UPS lost: status read failed! 23.664912 [D3] flush: Timeout 23.667615 [D3] send: Q1 23.857658 [D3] read: Q0 P11 23.857685 [D2] blazer_status: short reply 23.857694 [D1] Communications with UPS lost: status read failed! 25.666917 [D3] flush: Timeout 25.669547 [D3] send: Q1 25.873587 [D3] read: P1 P11 25.873620 [D2] blazer_status: short reply 25.873632 [D1] Communications with UPS lost: status read failed! 27.667921 [D3] flush: Timeout 27.670472 [D3] send: Q1 28.650913 [D3] read: Timeout 28.650945 [D2] blazer_status: short reply 28.650957 Communications with UPS lost: status read failed! 29.669913 [D3] flush: Timeout 29.672399 [D3] send: Q1 29.873442 [D3] read: Q0 Q11 29.873475 [D2] blazer_status: short reply 31.674928 [D3] flush: Timeout 31.677341 [D3] send: Q1 32.657908 [D3] read: Timeout 32.657941 [D2] blazer_status: short reply 33.676914 [D3] flush: Timeout 33.679257 [D3] send: Q1 34.659908 [D3] read: Timeout 34.659940 [D2] blazer_status: short reply 35.677899 [D3] flush: Timeout 35.680186 [D3] send: Q1 36.741910 [D3] read: Timeout 36.741943 [D2] blazer_status: short reply 37.722910 [D3] flush: Timeout 37.725110 [D3] send: Q1 38.885907 [D3] read: Timeout 38.885938 [D2] blazer_status: short reply 39.866906 [D3] flush: Timeout 39.869040 [D3] send: Q1 41.029913 [D3] read: Timeout 41.029945 [D2] blazer_status: short reply 42.010908 [D3] flush: Timeout 42.013959 [D3] send: Q1 42.994909 [D3] read: Timeout 42.994940 [D2] blazer_status: short reply 44.012911 [D3] flush: Timeout 44.015893 [D3] send: Q1 44.996923 [D3] read: Timeout 44.996951 [D2] blazer_status: short reply

zykh commented 6 years ago

Thanks for the logs -- so the errors are actually timeouts... we could try increasing the allowed time, but I'm not so sure this will solve the issue.

Before the problems with the COM port (I guess nothing has been updated/changed in your system concurrently a couple of weeks ago, causing regressions), did you ever try using the device with USB? Perhaps, the USB issues have always been there, just unnoticed, and they are not related to the problems with the COM port... or, maybe, the device is just dying (you know... nothing lasts forever, even cold november rain...). Either way, at first glance, I'm inclined to think that the problem is the device itself, not the OS, but nonetheless, do you have a chance to test it with a Linux-ish system?

Also, I think the other problem you mentioned with usbhid-ups is not related: feel free to open a new issue just for that if you still experience it.

dmilith commented 3 years ago

Same on FreeBSD 12.2… Wonder if anyone tried on 13.x?

kosfango commented 3 years ago

Same on FreeBSD 12.2… Wonder if anyone tried on 13.x?

If you read this thread, I had two different issues, fist with "classic ippon" the second with usbhid-ups based ippon with lcd screen. So first issue was in Ippon com/usb - interface died and I replaced the UPS to another. However, issue with usbhid-ups based Ippon is still unsolved. I didn't tested it on 12 or 13 FreeBSD. I suspect that issue in the driver...

dmilith commented 3 years ago

@kosfango In my case it's RPI2 on FreeBSD 12.2, I'm using "ETA UPS 1600 sinus", which is blazer_usb-compatible since it uses Megatec protocol.

The same blaze_usb driver works nicely on other RPI3 using the Debian system… so libusb-issue idea may also be a thing here. I'm open to help or test it out since FreeBSD is my system of choice :)

xtronics commented 2 years ago

I have had the similar issue on two Debian boxes running bullseye now - 

Jan 16 06:52:21 host-1 upscode2[1998]: Communications with UPS lost: Empty value from UPS for UPDS MOFFF!
Jan 16 06:52:21 host-1 upsd[2000]: Data for UPS [host-1] is stale - check driver
Jan 16 06:52:24 host-1 upsmon[2003]: Poll UPS [host-1@localhost] failed - Data stale
Jan 16 06:52:24 host-1 upsmon[2003]: Communications with UPS host-1@localhost lost
Jan 16 06:52:26 host-1 upscode2[1998]: Communications with UPS re-established
Jan 16 06:52:26 host-1 upsd[2000]: UPS [host-1] data is no longer stale
Jan 16 06:52:44 host-1 upsmon[2003]: Communications with UPS host-1@localhost established

Jan 15 23:52:12 host-2 upscode2[2363]: Communications with UPS lost: Empty string from UPS for UPDS!
Jan 15 23:52:20 host-2 upsmon[2368]: Poll UPS [host-2@localhost] failed - Data stale
Jan 15 23:52:40 host-2 upsmon[2368]: Poll UPS [host-2@localhost] failed - Data stale
Jan 15 23:52:52 host-2 upscode2[2363]: Communications with UPS lost: Empty string from UPS for UPDS!
Jan 15 23:53:00 host-2 upsmon[2368]: Poll UPS [host-2@localhost] failed - Data stale
Jan 15 23:53:00 host-2 upsmon[2368]: UPS host-2@localhost is unavailable
Jan 15 23:53:20 host-2 upsmon[2368]: Poll UPS [host-2@localhost] failed - Data stale
Jan 15 23:53:32 host-2 upscode2[2363]: Communications with UPS lost: Empty string from UPS for UPDS!
Jan 15 23:53:40 host-2 upsmon[2368]: Poll UPS [host-2@localhost] failed - Data stale
Jan 15 23:54:00 host-2 upsmon[2368]: Poll UPS [host-2@localhost] failed - Data stale
Jan 15 23:54:12 host-2 upscode2[2363]: Communications with UPS lost: Empty string from UPS for UPDS!
Jan 15 23:54:20 host-2 upsmon[2368]: Poll UPS [host-2@localhost] failed - Data stale
Jan 15 23:54:40 host-2 upsmon[2368]: Poll UPS [host-2@localhost] failed - Data stale
Jan 15 23:54:52 host-2 upscode2[2363]: Communications with UPS lost: Empty string from UPS for UPDS!
Jan 15 23:55:00 host-2 upsmon[2368]: Poll UPS [host-2@localhost] failed - Data stale
Jan 15 23:55:20 host-2 upsmon[2368]: Poll UPS [host-2@localhost] failed - Data stale
Jan 15 23:55:32 host-2 upscode2[2363]: Communications with UPS lost: Empty string from UPS for UPDS!
Jan 15 23:55:40 host-2 upsmon[2368]: Poll UPS [host-2@localhost] failed - Data stale
Jan 15 23:56:00 host-2 upsmon[2368]: Poll UPS [host-2@localhost] failed - Data stale
Jan 15 23:56:12 host-2 upscode2[2363]: Warning: excessive comm failures, limiting error reporting
Jan 15 23:56:12 host-2 upscode2[2363]: Communications with UPS lost: Empty string from UPS for UPDS!

I'm wondering if it is related to the load on the machine? - a partial workaround might be?: (I did both - but the problem is not constant so YMMV)

Increased pollfreq - I was wondering if the UPS itself was having trouble keeping up - not likely.. POLLFREQ 25

I increased the time delay a bit - NOCOMMWARNTIME 400

But it could be that the bug is actually in the UPSs themselves (Powerware 5119).. I've seen this problem show up sporadically for some years now.. But with the newer version in bullseye - more frequently now?

This is using USB-2-serial converters based on:

0403:6001 Future Technology Devices International, Ltd FT232 Serial (UART) IC

These FTDI chips pretty much set the standard - never had any problems with them in the many other applications I've used them in.

Hard to figure-out when it mostly works..

jimklimov commented 2 years ago

but with the newer version in bullseye

Did this refer to packaged NUT? If so, distros usually package (and patch over) official releases, so likely NUT 2.7.4 which is a few years old now. Hard work is actively in progress to release a good 2.7.5 as soon as we're confident in it.

If you could test a local build of NUT master branch (now including libusb-1.0 support, which should be more stable as a library than libusb-0.1), and let us know if it works (at all? ;] better?) for you, would be great.

Also, regarding "longer timeouts" commented above, the libusb-1.0(+0.1) branch changes merged recently included a bump from 250ms to 750ms for some operations, that might help here, if that is the problem.