Denis Serov
2012-Sep-11 17:18 UTC
[Nut-upsuser] Back UPS ES and data stale with disconnected device
Hello NUT Team! I continue playing with NUT for Windows and USBHID-UPS driver I've got from Frederic to fix "Data Stale" problem. It seems there is something wrong when Network UPS Tools service is starting with disconnected USB cable. UPSMON is writing "Data Stale" to output and continue do it infinitely, even the cable is connected back. Here is a short log: Network UPS Tools upsmon 2.6.5-3691:3709M 0.000000 UPS: upsa at 192.168.10.200 (master) (power value 1) 0.015600 Using power down flag file C:\killpower 0.015600 debug level is '5' 0.015600 Trying to connect to UPS [upsa at 192.168.10.200] 0.031200 Login on UPS [upsa at 192.168.10.200] failed - got [ERR ACCESS-DENIED] 0.031200 Current power value: 1 0.046800 Minimum power value: 1 5.054409 pollups: upsa at 192.168.10.200 5.054409 get_var: upsa at 192.168.10.200 / status 5.054409 Poll UPS [upsa at 192.168.10.200] failed - Data stale 5.070009 do_notify: ntype 0x0005 (COMMBAD) 5.070009 Communications with UPS upsa at 192.168.10.200 lost 5.085609 Current power value: 1 5.085609 Minimum power value: 1 10.097895 pollups: upsa at 192.168.10.200 10.097895 get_var: upsa at 192.168.10.200 / status 10.097895 Poll UPS [upsa at 192.168.10.200] failed - Data stale 10.113495 do_notify: ntype 0x0008 (NOCOMM) 10.113495 UPS upsa at 192.168.10.200 is unavailable 10.129095 Current power value: 1 10.129095 Minimum power value: 1 15.134979 pollups: upsa at 192.168.10.200 15.134979 get_var: upsa at 192.168.10.200 / status 15.134979 Poll UPS [upsa at 192.168.10.200] failed - Data stale 15.150579 Current power value: 1 15.150579 Minimum power value: 1 20.158188 pollups: upsa at 192.168.10.200 20.158188 get_var: upsa at 192.168.10.200 / status 20.158188 Poll UPS [upsa at 192.168.10.200] failed - Data stale ... But if the cable is already connected when the service is starting, it catches COMMBAD (cable disconnected) and COMMOK (cable connected again) notifications: Network UPS Tools upsmon 2.6.5-3691:3709M 0.000000 UPS: upsa at 192.168.10.200 (master) (power value 1) 0.015600 Using power down flag file C:\killpower 0.015600 debug level is '5' 0.031200 Trying to connect to UPS [upsa at 192.168.10.200] 0.031200 Login on UPS [upsa at 192.168.10.200] failed - got [ERR ACCESS-DENIED] 0.046800 Current power value: 1 0.046800 Minimum power value: 1 5.054409 pollups: upsa at 192.168.10.200 5.054409 get_var: upsa at 192.168.10.200 / status 5.054409 parse_status: [OL] 5.070009 parsing: [OL] 5.070009 ups_on_line: upsa at 192.168.10.200 (first time) 5.070009 Current power value: 1 5.085609 Minimum power value: 1 10.093218 pollups: upsa at 192.168.10.200 10.093218 get_var: upsa at 192.168.10.200 / status 10.093218 parse_status: [OL] 10.108818 parsing: [OL] 10.108818 ups_on_line: upsa at 192.168.10.200 (no change) 10.108818 Current power value: 1 10.124418 Minimum power value: 1 15.125250 pollups: upsa at 192.168.10.200 15.130250 get_var: upsa at 192.168.10.200 / status 15.136251 parse_status: [OL] 15.140251 parsing: [OL] 15.143251 ups_on_line: upsa at 192.168.10.200 (no change) 15.151252 Current power value: 1 15.155252 Minimum power value: 1 20.164865 pollups: upsa at 192.168.10.200 20.164865 get_var: upsa at 192.168.10.200 / status 20.164865 Poll UPS [upsa at 192.168.10.200] failed - Data stale 20.180465 do_notify: ntype 0x0005 (COMMBAD) 20.180465 Communications with UPS upsa at 192.168.10.200 lost 20.196065 Current power value: 1 20.196065 Minimum power value: 1 25.211951 pollups: upsa at 192.168.10.200 25.211951 get_var: upsa at 192.168.10.200 / status 25.211951 Poll UPS [upsa at 192.168.10.200] failed - Data stale 25.227551 Current power value: 1 25.227551 Minimum power value: 1 30.236992 pollups: upsa at 192.168.10.200 30.236992 get_var: upsa at 192.168.10.200 / status 30.236992 parse_status: [OL] 30.252592 do_notify: ntype 0x0004 (COMMOK) 30.252592 Communications with UPS upsa at 192.168.10.200 established 30.268192 parsing: [OL] 30.268192 ups_on_line: upsa at 192.168.10.200 (no change) 30.268192 Current power value: 1 30.268192 Minimum power value: 1 ... Operating system is Windows 7 x64. I can send additional logs if it is necessary... Thanks, Denis
FredericBohe at Eaton.com
2012-Sep-12 12:21 UTC
[Nut-upsuser] Back UPS ES and data stale with disconnected device
?Hello Denis, There is no bug in what you are describing. NUT drivers are designed to kill themselves if they can not connect to their UPS device after their initialization. The behavior is the same on UNIX and Windows : at service start-up, all configured drivers are started, if they do not find their UPS, they die and are never automatically restarted. It leaves you with upsd, upsmon and the drivers which have successfully connected to their UPS. So the rule is: your hardware must be up and running before starting NUT. Regards, Fred -- Eaton Opensource Team - http://opensource.eaton.com ----------------------------- ----------------------------- ________________________________________ From: nut-upsuser-bounces+fredericbohe=eaton.com at lists.alioth.debian.org [nut-upsuser-bounces+fredericbohe=eaton.com at lists.alioth.debian.org] on behalf of Denis Serov [dns-srv at yandex.ru] Sent: Tuesday, September 11, 2012 7:18 PM To: nut-upsuser at lists.alioth.debian.org Subject: [Nut-upsuser] Back UPS ES and data stale with disconnected device Hello NUT Team! I continue playing with NUT for Windows and USBHID-UPS driver I've got from Frederic to fix "Data Stale" problem. It seems there is something wrong when Network UPS Tools service is starting with disconnected USB cable. UPSMON is writing "Data Stale" to output and continue do it infinitely, even the cable is connected back. Here is a short log: Network UPS Tools upsmon 2.6.5-3691:3709M 0.000000 UPS: upsa at 192.168.10.200 (master) (power value 1) 0.015600 Using power down flag file C:\killpower 0.015600 debug level is '5' 0.015600 Trying to connect to UPS [upsa at 192.168.10.200] 0.031200 Login on UPS [upsa at 192.168.10.200] failed - got [ERR ACCESS-DENIED] 0.031200 Current power value: 1 0.046800 Minimum power value: 1 5.054409 pollups: upsa at 192.168.10.200 5.054409 get_var: upsa at 192.168.10.200 / status 5.054409 Poll UPS [upsa at 192.168.10.200] failed - Data stale 5.070009 do_notify: ntype 0x0005 (COMMBAD) 5.070009 Communications with UPS upsa at 192.168.10.200 lost 5.085609 Current power value: 1 5.085609 Minimum power value: 1 10.097895 pollups: upsa at 192.168.10.200 10.097895 get_var: upsa at 192.168.10.200 / status 10.097895 Poll UPS [upsa at 192.168.10.200] failed - Data stale 10.113495 do_notify: ntype 0x0008 (NOCOMM) 10.113495 UPS upsa at 192.168.10.200 is unavailable 10.129095 Current power value: 1 10.129095 Minimum power value: 1 15.134979 pollups: upsa at 192.168.10.200 15.134979 get_var: upsa at 192.168.10.200 / status 15.134979 Poll UPS [upsa at 192.168.10.200] failed - Data stale 15.150579 Current power value: 1 15.150579 Minimum power value: 1 20.158188 pollups: upsa at 192.168.10.200 20.158188 get_var: upsa at 192.168.10.200 / status 20.158188 Poll UPS [upsa at 192.168.10.200] failed - Data stale ... But if the cable is already connected when the service is starting, it catches COMMBAD (cable disconnected) and COMMOK (cable connected again) notifications: Network UPS Tools upsmon 2.6.5-3691:3709M 0.000000 UPS: upsa at 192.168.10.200 (master) (power value 1) 0.015600 Using power down flag file C:\killpower 0.015600 debug level is '5' 0.031200 Trying to connect to UPS [upsa at 192.168.10.200] 0.031200 Login on UPS [upsa at 192.168.10.200] failed - got [ERR ACCESS-DENIED] 0.046800 Current power value: 1 0.046800 Minimum power value: 1 5.054409 pollups: upsa at 192.168.10.200 5.054409 get_var: upsa at 192.168.10.200 / status 5.054409 parse_status: [OL] 5.070009 parsing: [OL] 5.070009 ups_on_line: upsa at 192.168.10.200 (first time) 5.070009 Current power value: 1 5.085609 Minimum power value: 1 10.093218 pollups: upsa at 192.168.10.200 10.093218 get_var: upsa at 192.168.10.200 / status 10.093218 parse_status: [OL] 10.108818 parsing: [OL] 10.108818 ups_on_line: upsa at 192.168.10.200 (no change) 10.108818 Current power value: 1 10.124418 Minimum power value: 1 15.125250 pollups: upsa at 192.168.10.200 15.130250 get_var: upsa at 192.168.10.200 / status 15.136251 parse_status: [OL] 15.140251 parsing: [OL] 15.143251 ups_on_line: upsa at 192.168.10.200 (no change) 15.151252 Current power value: 1 15.155252 Minimum power value: 1 20.164865 pollups: upsa at 192.168.10.200 20.164865 get_var: upsa at 192.168.10.200 / status 20.164865 Poll UPS [upsa at 192.168.10.200] failed - Data stale 20.180465 do_notify: ntype 0x0005 (COMMBAD) 20.180465 Communications with UPS upsa at 192.168.10.200 lost 20.196065 Current power value: 1 20.196065 Minimum power value: 1 25.211951 pollups: upsa at 192.168.10.200 25.211951 get_var: upsa at 192.168.10.200 / status 25.211951 Poll UPS [upsa at 192.168.10.200] failed - Data stale 25.227551 Current power value: 1 25.227551 Minimum power value: 1 30.236992 pollups: upsa at 192.168.10.200 30.236992 get_var: upsa at 192.168.10.200 / status 30.236992 parse_status: [OL] 30.252592 do_notify: ntype 0x0004 (COMMOK) 30.252592 Communications with UPS upsa at 192.168.10.200 established 30.268192 parsing: [OL] 30.268192 ups_on_line: upsa at 192.168.10.200 (no change) 30.268192 Current power value: 1 30.268192 Minimum power value: 1 ... Operating system is Windows 7 x64. I can send additional logs if it is necessary... Thanks, Denis _______________________________________________ Nut-upsuser mailing list Nut-upsuser at lists.alioth.debian.org http://lists.alioth.debian.org/cgi-bin/mailman/listinfo/nut-upsuser