NUT package (2.8.0 and below)

n3by

Now after I deleted cron UPS schedule restart I don't have any more problems with lost communication, zero problems in 2 days !

Using upssched.conf & custom-upssched-cmd is the proper way to deal with lost communication if you ask me, no need to schedule a restart for UPS driver if communications is good.

edit:

I was to happy… worked only 2-3 days...

n3by

Something is NOT OK !

After 2-3 days without any problem today without any reason UPS communication went offline and no chance to be restored with the changes I made to
custom-upssched-cmd & upssched.conf

I think commands I defined there are not executed, syslog show no trace of NUT service restart.

I restarted manually the service but this problem continued… randomly.
even I changed:

DEADTIME 30
POLLFREQ 10
POLLFREQALERT 10
and
pollinterval = 10

No chance to fix for long term... communication go offline randomly.

Only pfsense reboot solved the UPS communication problem.

Definitely a NUT problem as I did not touched anything on UPS.

Any ideas ?
Do I need something else to set for upssched to work ??

I hope I don't have to return to cron schedule NUT restart… because to schedule a pfsense reboot every night for NUT to work properly it is not a good option.

doktornotor

Dude, how about changing your "NoName Polish brand" UPS for something that works, instead of wasting time and blaming NUT?

n3by

Nu chance yet "duck", Santa is not authorized to transport this devices yet.

If you use an UPS you will now that this problem is old and common to NUT UPS.

https://forum.pfsense.org/index.php?topic=33860.0
https://forum.pfsense.org/index.php?topic=78977.0
…
just search it if you want more...
https://duckduckgo.com/?q=nut+ups+lost+communication

If a reboot of pfsense fixed this problem after 2-3 days when it worked OK then are low chances to blame only the UPS hardware.

Cron seem a quick&dirty way to fix the problem and everybody recommend this because it is easy to implement... do you want to restart a process that it is working ok every 15 min, just to be sure ?

I think a better way to quick fix is to use monitor that will restart the driver/package only when it is required, ( this is the purpose of upssched.conf ) this is what I try to have it working properly, it already send you notification at defined event why not use that to restart the NUT driver if it is required & only when it is required.

p.s.
having this ( upssched.conf ) working properly will help everybody not only me !

dennypage

@n3by:

If a reboot of pfsense fixed this problem after 2-3 days when it worked OK then are low chances to blame only the UPS hardware.

Just the opposite. If a reboot is required to fix the issue, this guarantees that it is not a NUT problem. This leaves you with the USB controller kernel driver, the USB controller itself, the cabling and the UPS. The kernel driver is extremely unlikely, so we'll set that aside. This leaves us with the hardware.

Please do the following:

1. Confirm that you have a good quality USB cable.
2. Confirm that you are not using a hub.
3. Confirm that you have tried a different USB port on the host.
4. Check to see if usbconfig shows the device as still being present after the UPS goes offline.
5. Try unplugging the USB cable for 10 seconds instead of rebooting.

I suspect that what you will find in #4 is that the UPS no longer appears in the USB tree. In #5 I suspect you will find that unplugging the USB connection will cause the UPS to return to the tree.

Btw, the threads you referred to are not really pertinent to your issue. Please do the above steps first before going out to research more complicated situations. After the above steps, if you want to research more information on your issues, I would google for "NUT USB 0665 5161".

n3by

this time after ~1:30'after pfsense restart it happened again:

1 - Original USB UPS cable, not sure how good it is, I will try change it but for the moment I don't have another one.
2 - NO HUB - direct connection
3 - YES, the same.
4 - YES it is present, also present after unplugged and replugged cable.

ugen0.2: <usb to="" serial="" inno="" tech=""> at usbus0, cfg=0 md=HOST spd=LOW (1.5Mbps) pwr=ON (100mA)

  bLength = 0x0012
  bDescriptorType = 0x0001
  bcdUSB = 0x0110
  bDeviceClass = 0x0000  <probed by="" interface="" class="">
  bDeviceSubClass = 0x0000
  bDeviceProtocol = 0x0000
  bMaxPacketSize0 = 0x0008
  idVendor = 0x0665
  idProduct = 0x5161
  bcdDevice = 0x0002
  iManufacturer = 0x0001  <inno tech="">
  iProduct = 0x0002  <usb to="" serial="">
  iSerialNumber = 0x0000  <no string="">
  bNumConfigurations = 0x0001</no></usb></inno></probed></usb>

5- Not fixed automatically… fixed only after saved again the UPS Settings.

Any ideas why is not working properly custom-upssched-cmd ?

#!/bin/sh
NAME=`basename $0`
LOGGER="/usr/bin/logger -t $NAME"

case $1 in
	ups-no-comm)
		$LOGGER "Timer event '$1' fired, restart NUT..."
		/usr/local/etc/rc.d/nut.sh restart
        ;;
    *)
        $LOGGER "Unrecognized command: '$1'"
        ;;
esac

upssched.conf

CMDSCRIPT /usr/local/bin/custom-upssched-cmd

PIPEFN /tmp/upssched.pipe
LOCKFN /tmp/upssched.lock

AT NOCOMM * START-TIMER ups-no-comm 30
AT COMMBAD * START-TIMER ups-no-comm 30
AT COMMOK  * CANCEL-TIMER ups-no-comm COMMOK

![2016-12-20 21.35.31.jpg](/public/imported_attachments/1/2016-12-20 21.35.31.jpg)
![2016-12-20 21.35.31.jpg_thumb](/public/imported_attachments/1/2016-12-20 21.35.31.jpg_thumb)
![2016-12-20 21.35.39.jpg](/public/imported_attachments/1/2016-12-20 21.35.39.jpg)
![2016-12-20 21.35.39.jpg_thumb](/public/imported_attachments/1/2016-12-20 21.35.39.jpg_thumb)
![2016-12-20 21.38.07.jpg](/public/imported_attachments/1/2016-12-20 21.38.07.jpg)
![2016-12-20 21.38.07.jpg_thumb](/public/imported_attachments/1/2016-12-20 21.38.07.jpg_thumb)
![2016-12-20 21.56.42.jpg](/public/imported_attachments/1/2016-12-20 21.56.42.jpg)
![2016-12-20 21.56.42.jpg_thumb](/public/imported_attachments/1/2016-12-20 21.56.42.jpg_thumb)

n3by

It is a problem of user rights ?

![2016-12-20 22.09.06.jpg](/public/imported_attachments/1/2016-12-20 22.09.06.jpg)
![2016-12-20 22.09.06.jpg_thumb](/public/imported_attachments/1/2016-12-20 22.09.06.jpg_thumb)

dennypage

@n3by:

this time after ~1:30'after pfsense restart it happened again:

4 - YES it is present, also present after unplugged and replugged cable.
5- Not fixed automatically… fixed only after saved again the UPS Settings.

Re-saving the UPS settings just stops and starts NUT. Simpler to just restart the service.

You may be experiencing multiple communication issues. Previously, you had an event where restarting the service did not work, and you had to reboot the system, yes? It is this type of event that I'm asking you to run usbconfig for. Do you still have pollinterval set to 10 for testing? If not, please put it back as described above. If you are setting anything else, please remove it.

If you want to diagnose the source of the problem, I will do my best to help you. In the end, we will likely find that the UPS is the source of the problem. I know that this is not what you want to hear, but it's almost certainly the case. I'm not able to help you with upssched other than to tell you that working around communications errors is absolutely not what it's intended for.

dennypage

@n3by:

It is a problem of user rights ?

No.

n3by

This are the settings I have:

upsmon.conf

DEADTIME 30
POLLFREQ 10
POLLFREQALERT 10
SHUTDOWNCMD "/sbin/halt -p"

ups.conf

pollinterval = 10
default.battery.voltage.high = 13.7
default.battery.voltage.low = 11.5
runtimecal = 180,100,360,50
ignorelb
override.battery.charge.low = 50
override.battery.runtime.low = 600

attached img with usbconfig after error, before I unplugged the cable.

![2016-12-20 22.16.17.jpg](/public/imported_attachments/1/2016-12-20 22.16.17.jpg)
![2016-12-20 22.16.17.jpg_thumb](/public/imported_attachments/1/2016-12-20 22.16.17.jpg_thumb)

dennypage

@n3by:

Any ideas why is not working properly custom-upssched-cmd ?

And since you are probably are still thinking about this… yes, because your UPS is going offline for longer than it takes to restart the NUT service.

dennypage

@n3by:

ups.conf

pollinterval = 10
default.battery.voltage.high = 13.7
default.battery.voltage.low = 11.5
runtimecal = 180,100,360,50
ignorelb
override.battery.charge.low = 50
override.battery.runtime.low = 600

This cannot be your ups.conf as there is no actual ups definition. Please do not edit files by hand. Go into the UPS configuration (Services / UPS / Settings), remove everything from the advanced section except for "pollinterval=10", and save the configuration. This is where we will start.

Please post the contents of cat /usr/local/etc/nut/ups.conf, /usr/local/etc/nut/upsmon.conf, and /usr/local/etc/nut/upsd.conf for confirmation.

n3by

I have this config because I wanted the firewall to shutdown quick ( ~1-2 min ) if power is lost and not when UPS will send battery low.
I also have another computer - file server on this ups that monitor by a script I made if firewall is ON => UPS is online; other way will shut down ( it ping LAN interface ).

All this because I can power ON all this computers by IAMT - remote but this require UPS to be ON; if battery is empty then UPS will go OFF and will stay OFF even if main power will restore.

With this 2 computers normal running on UPS I have a load of ~20% ( 90w ) so plenty of time for UPS to stay ON when power is lost and this 2 computers will also quick power OFF.

I made a small change increasing timer to 60s in upssched.conf and changed

custom-upssched-cmd

#!/bin/sh
NAME=`basename $0`
LOGGER="/usr/bin/logger -t $NAME"

case $1 in
	ups-no-comm)
		$LOGGER "Timer event '$1' fired, restart NUT..."
		/usr/local/etc/rc.d/nut.sh stop
		sleep 30
		/usr/local/etc/rc.d/nut.sh start
        ;;
    *)
        $LOGGER "Unrecognized command: '$1'"
        ;;
esac

![2016-12-20 22.50.12.jpg](/public/imported_attachments/1/2016-12-20 22.50.12.jpg)
![2016-12-20 22.50.12.jpg_thumb](/public/imported_attachments/1/2016-12-20 22.50.12.jpg_thumb)

dennypage

@n3by:

I have this config because I wanted the firewall to shutdown quick ( ~1-2 min ) if power is lost and not when UPS will send battery low.

I understand what you are trying to do, however your current configuration does not actually do this. Most of the configuration is in the wrong place. It is unfortunate that NUT generally ignores invalid configuration rather than generating an error. Anyway, save this stuff for later–it's just creating complication in diagnosing the issue.

If you want help you will need to listen and stop changing things willy-nilly. Stop messing around with upssched.conf. Stop messing around with the advanced settings. Remove everything in the advanced section except "pollinterval=10" in the ups.conf section. Don't edit any files by hand.

If you don't want help, that's okay too. I won't be offended at all. Really.

n3by

/usr/local/etc/nut/ups.conf

pollinterval = 10

[ActiveJet]
driver=blazer_usb
port=auto

/usr/local/etc/nut/upsmon.conf

MONITOR ActiveJet 1 monuser 09959dba1bb426d94a50 master
SHUTDOWNCMD "/sbin/shutdown -p +0"
POWERDOWNFLAG /etc/killpower
NOTIFYCMD /usr/local/pkg/nut/nut_email.php
NOTIFYFLAG ONLINE   SYSLOG+WALL+EXEC
NOTIFYFLAG ONBATT   SYSLOG+WALL+EXEC
NOTIFYFLAG LOWBATT  SYSLOG+WALL+EXEC
NOTIFYFLAG FSD	  SYSLOG+WALL+EXEC
NOTIFYFLAG COMMOK   SYSLOG+WALL+EXEC
NOTIFYFLAG COMMBAD  SYSLOG+WALL+EXEC
NOTIFYFLAG SHUTDOWN SYSLOG+WALL+EXEC
NOTIFYFLAG REPLBATT SYSLOG+WALL+EXEC
NOTIFYFLAG NOCOMM   SYSLOG+WALL+EXEC
NOTIFYFLAG NOPARENT SYSLOG+WALL+EXEC

SHUTDOWNCMD "/sbin/halt -p"

/usr/local/etc/nut/upsd.conf

LISTEN 127.0.0.1
LISTEN ::1

![2016-12-21 10.36.41.jpg](/public/imported_attachments/1/2016-12-21 10.36.41.jpg)
![2016-12-21 10.36.41.jpg_thumb](/public/imported_attachments/1/2016-12-21 10.36.41.jpg_thumb)

dennypage

Okay. When the problem next occurs, please do the following:

1. Grab system log entries from Status / System Logs / System / General. Logs at the time of the event and the preceding few minutes. Plus any log entries with "usb" "ups" or "nut" since startup even if not near the event.
2. Log in and run "usbconfig dump_device_desc".
3. Attempt restart of the UPS service (Status / Services).
4. If #3 does not bring the service back, unplug the host end of the USB cable for 10 seconds, then attempt service restart again.
5. If #3 and #4 do not bring the service back, run usbconfig again, and then reboot.

Please post the results.

dennypage

Btw, you can remove your SHUTDOWNCMD from the advanced settings as well. It does the same thing as the default shutdown command but without notice. No advantage to this.

n3by

Dec 22 06:00:00 firewall1 xinetd[51686]: Starting reconfiguration
Dec 22 06:00:00 firewall1 xinetd[51686]: Swapping defaults
Dec 22 06:00:00 firewall1 xinetd[51686]: readjusting service 6969-udp
Dec 22 06:00:00 firewall1 xinetd[51686]: Reconfigured: new=0 old=1 dropped=0 (services)
Dec 22 06:01:56 firewall1 php: [pfBlockerNG] Starting cron process.
Dec 22 06:05:09 firewall1 php: [pfBlockerNG] No changes to Firewall rules, skipping Filter Reload
Dec 22 06:15:00 firewall1 xinetd[51686]: Starting reconfiguration
Dec 22 06:15:00 firewall1 xinetd[51686]: Swapping defaults
Dec 22 06:15:00 firewall1 xinetd[51686]: readjusting service 6969-udp
Dec 22 06:15:00 firewall1 xinetd[51686]: Reconfigured: new=0 old=1 dropped=0 (services)
Dec 22 06:21:18 firewall1 blazer_usb[5521]: Permissions problem: Input/output error
Dec 22 06:21:18 firewall1 upsd[5189]: Can't connect to UPS [ActiveJet] (blazer_usb-ActiveJet): No such file or directory
Dec 22 06:21:19 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:21:19 firewall1 upsmon[4542]: Communications with UPS ActiveJet lost
Dec 22 06:21:19 firewall1 php-cgi: nut_email.php: Message sent to  xxxxxxxxxxxxxx OK
Dec 22 06:21:24 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:21:29 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:21:34 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:21:39 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:21:44 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:21:49 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:21:54 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:21:59 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:22:04 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:22:09 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:22:14 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:22:19 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:22:24 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:22:29 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:22:34 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:22:39 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:22:44 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:22:49 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:22:54 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:22:59 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:23:04 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:23:09 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:23:14 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:23:19 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:23:24 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:23:29 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:23:34 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:23:39 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:23:44 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:23:49 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:23:54 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:23:59 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:24:04 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:24:09 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:24:14 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:24:19 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:24:24 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:24:29 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:24:34 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:24:39 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:24:44 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:24:49 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:24:54 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:24:59 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:25:04 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:25:09 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:25:14 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:25:19 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:25:24 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:25:29 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:25:34 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:25:39 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:25:44 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:25:49 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:25:54 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:25:59 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:26:04 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:26:09 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:26:14 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:26:14 firewall1 upsmon[4542]: UPS ActiveJet is unavailable
Dec 22 06:26:15 firewall1 php-cgi: nut_email.php: Message sent to xxxxxxxxxxxxxx OK
Dec 22 06:26:18 firewall1 upsd[5189]: Can't connect to UPS [ActiveJet] (blazer_usb-ActiveJet): No such file or directory
Dec 22 06:26:19 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:26:24 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 06:26:29 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
...
Dec 22 08:59:43 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 08:59:48 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 08:59:53 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 08:59:58 firewall1 upsmon[4542]: Poll UPS [ActiveJet] failed - Driver not connected
....

usbconfig dump_device_desc

ugen0.1: <uhci root="" hub="" intel=""> at usbus0, cfg=0 md=HOST spd=FULL (12Mbps) pwr=SAVE (0mA)

  bLength = 0x0012
  bDescriptorType = 0x0001
  bcdUSB = 0x0100
  bDeviceClass = 0x0009  <hub>
  bDeviceSubClass = 0x0000
  bDeviceProtocol = 0x0000
  bMaxPacketSize0 = 0x0040
  idVendor = 0x0000
  idProduct = 0x0000
  bcdDevice = 0x0100
  iManufacturer = 0x0001  <intel>
  iProduct = 0x0002  <uhci root="" hub="">
  iSerialNumber = 0x0000  <no string="">
  bNumConfigurations = 0x0001

ugen3.1: <ehci root="" hub="" intel=""> at usbus3, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=SAVE (0mA)

  bLength = 0x0012
  bDescriptorType = 0x0001
  bcdUSB = 0x0200
  bDeviceClass = 0x0009  <hub>
  bDeviceSubClass = 0x0000
  bDeviceProtocol = 0x0001
  bMaxPacketSize0 = 0x0040
  idVendor = 0x0000
  idProduct = 0x0000
  bcdDevice = 0x0100
  iManufacturer = 0x0001  <intel>
  iProduct = 0x0002  <ehci root="" hub="">
  iSerialNumber = 0x0000  <no string="">
  bNumConfigurations = 0x0001

ugen2.1: <uhci root="" hub="" intel=""> at usbus2, cfg=0 md=HOST spd=FULL (12Mbps) pwr=SAVE (0mA)

  bLength = 0x0012
  bDescriptorType = 0x0001
  bcdUSB = 0x0100
  bDeviceClass = 0x0009  <hub>
  bDeviceSubClass = 0x0000
  bDeviceProtocol = 0x0000
  bMaxPacketSize0 = 0x0040
  idVendor = 0x0000
  idProduct = 0x0000
  bcdDevice = 0x0100
  iManufacturer = 0x0001  <intel>
  iProduct = 0x0002  <uhci root="" hub="">
  iSerialNumber = 0x0000  <no string="">
  bNumConfigurations = 0x0001

ugen1.1: <uhci root="" hub="" intel=""> at usbus1, cfg=0 md=HOST spd=FULL (12Mbps) pwr=SAVE (0mA)

  bLength = 0x0012
  bDescriptorType = 0x0001
  bcdUSB = 0x0100
  bDeviceClass = 0x0009  <hub>
  bDeviceSubClass = 0x0000
  bDeviceProtocol = 0x0000
  bMaxPacketSize0 = 0x0040
  idVendor = 0x0000
  idProduct = 0x0000
  bcdDevice = 0x0100
  iManufacturer = 0x0001  <intel>
  iProduct = 0x0002  <uhci root="" hub="">
  iSerialNumber = 0x0000  <no string="">
  bNumConfigurations = 0x0001

ugen6.1: <uhci root="" hub="" intel=""> at usbus6, cfg=0 md=HOST spd=FULL (12Mbps) pwr=SAVE (0mA)

  bLength = 0x0012
  bDescriptorType = 0x0001
  bcdUSB = 0x0100
  bDeviceClass = 0x0009  <hub>
  bDeviceSubClass = 0x0000
  bDeviceProtocol = 0x0000
  bMaxPacketSize0 = 0x0040
  idVendor = 0x0000
  idProduct = 0x0000
  bcdDevice = 0x0100
  iManufacturer = 0x0001  <intel>
  iProduct = 0x0002  <uhci root="" hub="">
  iSerialNumber = 0x0000  <no string="">
  bNumConfigurations = 0x0001

ugen5.1: <uhci root="" hub="" intel=""> at usbus5, cfg=0 md=HOST spd=FULL (12Mbps) pwr=SAVE (0mA)

  bLength = 0x0012
  bDescriptorType = 0x0001
  bcdUSB = 0x0100
  bDeviceClass = 0x0009  <hub>
  bDeviceSubClass = 0x0000
  bDeviceProtocol = 0x0000
  bMaxPacketSize0 = 0x0040
  idVendor = 0x0000
  idProduct = 0x0000
  bcdDevice = 0x0100
  iManufacturer = 0x0001  <intel>
  iProduct = 0x0002  <uhci root="" hub="">
  iSerialNumber = 0x0000  <no string="">
  bNumConfigurations = 0x0001

ugen4.1: <uhci root="" hub="" intel=""> at usbus4, cfg=0 md=HOST spd=FULL (12Mbps) pwr=SAVE (0mA)

  bLength = 0x0012
  bDescriptorType = 0x0001
  bcdUSB = 0x0100
  bDeviceClass = 0x0009  <hub>
  bDeviceSubClass = 0x0000
  bDeviceProtocol = 0x0000
  bMaxPacketSize0 = 0x0040
  idVendor = 0x0000
  idProduct = 0x0000
  bcdDevice = 0x0100
  iManufacturer = 0x0001  <intel>
  iProduct = 0x0002  <uhci root="" hub="">
  iSerialNumber = 0x0000  <no string="">
  bNumConfigurations = 0x0001

ugen7.1: <ehci root="" hub="" intel=""> at usbus7, cfg=0 md=HOST spd=HIGH (480Mbps) pwr=SAVE (0mA)

  bLength = 0x0012
  bDescriptorType = 0x0001
  bcdUSB = 0x0200
  bDeviceClass = 0x0009  <hub>
  bDeviceSubClass = 0x0000
  bDeviceProtocol = 0x0001
  bMaxPacketSize0 = 0x0040
  idVendor = 0x0000
  idProduct = 0x0000
  bcdDevice = 0x0100
  iManufacturer = 0x0001  <intel>
  iProduct = 0x0002  <ehci root="" hub="">
  iSerialNumber = 0x0000  <no string="">
  bNumConfigurations = 0x0001

ugen5.2: <usb to="" serial="" inno="" tech=""> at usbus5, cfg=0 md=HOST spd=LOW (1.5Mbps) pwr=ON (100mA)

  bLength = 0x0012
  bDescriptorType = 0x0001
  bcdUSB = 0x0110
  bDeviceClass = 0x0000  <probed by="" interface="" class="">
  bDeviceSubClass = 0x0000
  bDeviceProtocol = 0x0000
  bMaxPacketSize0 = 0x0008
  idVendor = 0x0665
  idProduct = 0x5161
  bcdDevice = 0x0002
  iManufacturer = 0x0001  <retrieving string="" failed="">
  iProduct = 0x0002  <retrieving string="" failed="">
  iSerialNumber = 0x0000  <no string="">
  bNumConfigurations = 0x0001</no></retrieving></retrieving></probed></usb></no></ehci></intel></hub></ehci></no></uhci></intel></hub></uhci></no></uhci></intel></hub></uhci></no></uhci></intel></hub></uhci></no></uhci></intel></hub></uhci></no></uhci></intel></hub></uhci></no></ehci></intel></hub></ehci></no></uhci></intel></hub></uhci>

Service restarted OK from Status-Services

Dec 22 09:07:44 	upsd 	20160 	User monuser@127.0.0.1 logged into UPS [ActiveJet]
Dec 22 09:07:44 	upsd 	20160 	Connected to UPS [ActiveJet]: blazer_usb-ActiveJet
Dec 22 09:07:43 	blazer_usb 	20285 	Startup successful
Dec 22 09:07:42 	upsd 	20160 	Startup successful
Dec 22 09:07:42 	upsd 	20019 	Can't connect to UPS [ActiveJet] (blazer_usb-ActiveJet): No such file or directory
Dec 22 09:07:42 	upsd 	20019 	listening on 127.0.0.1 port 3493
Dec 22 09:07:42 	upsd 	20019 	listening on ::1 port 3493
Dec 22 09:07:41 	upsmon 	18970 	Startup successful
Dec 22 09:07:41 	upsd 	5189 	Signal 15: exiting
Dec 22 09:07:41 	upsd 	5189 	mainloop: Interrupted system call
Dec 22 09:07:41 	upsd 	5189 	User monuser@127.0.0.1 logged out from UPS [ActiveJet]
Dec 22 09:07:41 	upsmon 	4542 	Signal 15: exiting
Dec 22 09:07:38 	upsmon 	4542 	Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 09:07:33 	upsmon 	4542 	Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 09:07:28 	upsmon 	4542 	Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 09:07:23 	upsmon 	4542 	Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 09:07:18 	upsmon 	4542 	Poll UPS [ActiveJet] failed - Driver not connected
Dec 22 09:07:13 	upsmon 	4542 	Poll UPS [ActiveJet] failed - Driver not connected
...

p.s.
it looks like upssched is not executed at all because it not stop the service, and this is wrong.
I need a script that will restart the UPS service, only if communication with UPS is lost and upsched is not doing this at the moment.

edit
I think I understand why is not executed… normal is executed from NOTIFYCMD which now is substituted by nut_email.php...

dennypage

@n3by:


Dec 22 06:21:18 firewall1 blazer_usb[5521]: Permissions problem: Input/output error

Pretty sure I know what the problem is. Going to take a bit of research to find out if there is a work-around.

dennypage

Here's my analysis. Short version: You have a flakey UPS and are also encountering a kernel bug.

The UPS is using an inbuilt Cypress 1.0 USB to serial chip (vendor 0x0665 product 0x5161). What kicks the problem off is that the chip flakes out briefly. This appears to be a pretty well known issue with this chip.

When this happens at the wrong moment, it triggers a bug in the FreeBSD kernel. The kernel gets confused. It's one of those "this should never happen" bugs. When it does happen, it triggers a safety check that causes EPERM (not permitted) to be returned in response to a read or write operations on the USB device. The error value EPERM is incorrect. It should return EIO or ENXIO.

The NUT Blazer driver (or Qx driver) would correctly handle EIO or ENXIO, and attempt close/reopen the device. However the driver interprets EPERM for any USB command to be a fatal error, causing the driver to exit. One could argue that the NUT driver could be changed to treat EPERM the same as ENXIO for FreeBSD, but this would create problems with driver when there are actual permission problems. And it really isn't their bug.

I don't have a device that produces this behavior, so I cannot effectively debug the root cause of the kernel issue. The best I can do is to submit a patch to the FreeBSD folk to change the return value from the safety check, which I will do. However I expect that it will take a long time for this change to make its way into a released kernel.

In the interim, several choices come to mind:

1. Get a new UPS. Something that doesn't use the old Cypress USB chip.
2. Build a custom kernel to use with pfSense. This is a very bad idea, and I mention it for completeness only.
3. Build a custom version of the NUT Blazer driver. If you want to do this, let me know and I will send you a patch that will work around the problem. You will need a working FreeBSD 10.3 development environment to do the build.
4. Move the UPS to another host (non FreeBSD), and use NUT's remote monitoring feature from pfSense.
5. Try to work around it with scripts. This approach is fine as long as there isn't a power failure. If the problem happens in close proximity to a power failure, this may well result in failure of the shutdown function.

Option #1 is your best bet. If you can't do that, then I would look at #4. I don't know what your other hosts are, but if one is a Linux box that you can run NUT on, this is a good way to go. If you cannot do #1 or #4, let me know and I can suggest an alternate approach for #5.

Sorry to not have better news to offer.