2 issues/behaviours with attached and identified UPS

Status
Not open for further replies.

deed

Cadet
Joined
Oct 11, 2014
Messages
7
Hi,

I've recently bought a re-branded UPS and tried to see if FreeNAS will support it.
It's basically using ViewPower UPS UI management system so I took a wild guess (based on other posts here) and tried to define with 'nutdrv_qx' drive.

This is how it's defined on FreeNAS UI:
http://i.imgur.com/WXk6QGS.png

Upon turning on the UPS service:
Code:
[SOMEUSER@freenas] /% upsc ups@localhost
battery.charge: 100
battery.voltage: 13.50
battery.voltage.high: 13.00
battery.voltage.low: 10.40
battery.voltage.nominal: 12.0
device.type: ups
driver.flag.novendor: enabled
driver.name: nutdrv_qx
driver.parameter.pollfreq: 30
driver.parameter.pollinterval: 10
driver.parameter.port: auto
driver.version: 2.7.1
driver.version.data: Mustek 0.01
driver.version.internal: 0.01
input.current.nominal: 3.0
input.frequency: 50.0
input.frequency.nominal: 50
input.voltage: 232.8
input.voltage.fault: 234.9
input.voltage.nominal: 230
output.voltage: 234.9
ups.beeper.status: enabled
ups.delay.shutdown: 30
ups.delay.start: 180
ups.load: 2
ups.productid: 5161
ups.status: OL
ups.type: offline / line interactive
ups.vendorid: 0665


So far so good ? Thats what I thought (experts might detect an error in that output maybe ?).

Tried to plug the UPS power cable to the wall and debug the footer 'console messages':
Code:
Oct 11 16:18:38 freenas upsmon[17348]: UPS ups on battery
Oct 11 16:19:08 freenas upssched-cmd: issuing shutdown
Oct 11 16:19:08 freenas upsmon[17348]: Executing automatic power-fail shutdown
Oct 11 16:19:08 freenas upsmon[17348]: Auto logout and shutdown proceeding
Oct 11 16:19:38 freenas shutdown: power-down by root:


And it's off. cool ! right ?

[1] 1st Problem - Testing UPS shut down machine unable to recognize the UPS upon start up:
Problem is, after I plugged the UPS back to power, and started the FreeNAS machine I get messages that the UPS is unable to connect:
Code:
Oct 11 16:22:54 freenas upsmon[2417]: UPS [ups]: connect failed: Connection failure: Connection refused
Oct 11 16:22:54 freenas upsmon[2417]: Communications with UPS ups lost
Oct 11 16:22:59 freenas upsmon[2417]: UPS [ups]: connect failed: Connection failure: Connection refused
Oct 11 16:22:59 freenas upsmon[2417]: UPS ups is unavailable
Oct 11 16:24:19 freenas upsmon[2417]: UPS [ups]: connect failed: Connection failure: Connection refused
Oct 11 16:24:49 freenas last message repeated 6 times
Oct 11 16:26:49 freenas last message repeated 24 times
Oct 11 16:28:04 freenas last message repeated 15 times
Oct 11 16:28:04 freenas upsmon[2417]: UPS ups is unavailable
Oct 11 16:28:09 freenas upsmon[2417]: UPS [ups]: connect failed: Connection failure: Connection refused
etc...


Control Services -> turned UPS Off and On again, and we were back online with the UPS:
Code:
Oct 11 16:32:03 freenas notifier: nut not running? (check /var/db/nut/upsd.pid).
Oct 11 16:32:03 freenas notifier: nut_upsmon not running? (check /var/db/nut/upsmon.pid).
Oct 11 16:32:03 freenas notifier: nut_upslog not running? (check /var/db/nut/upslog.pid).
Oct 11 16:32:03 freenas notifier: nut not running? (check /var/db/nut/upsd.pid).
Oct 11 16:32:03 freenas root: Unknown USB device: vendor 0x0665 product 0x5161 bus uhub2
Oct 11 16:32:04 freenas notifier: Using protocol: Mustek 0.01
Oct 11 16:32:04 freenas notifier: No values for battery high/low voltages
Oct 11 16:32:04 freenas notifier: Using 'guesstimation' (low: 10.400000, high: 13.000000)!
Oct 11 16:32:04 freenas notifier: Battery runtime will not be calculated (runtimecal not set)
Oct 11 16:32:05 freenas notifier: Network UPS Tools - UPS driver controller 2.7.1
Oct 11 16:32:05 freenas notifier: Starting nut.
Oct 11 16:32:05 freenas notifier: fopen /var/db/nut/upsd.pid: No such file or directory
Oct 11 16:32:05 freenas notifier: listening on 127.0.0.1 port 3493
Oct 11 16:32:05 freenas notifier: Connected to UPS [ups]: nutdrv_qx-ups
Oct 11 16:32:05 freenas notifier: nut_upsmon not running? (check /var/db/nut/upsmon.pid).
Oct 11 16:32:05 freenas notifier: Starting nut_upsmon.
Oct 11 16:32:05 freenas notifier: kill: No such process
Oct 11 16:32:05 freenas notifier: UPS: ups (master) (power value 1)
Oct 11 16:32:05 freenas notifier: nut_upslog not running? (check /var/db/nut/upslog.pid).
Oct 11 16:32:05 freenas notifier: Starting nut_upslog.


again upsc ups@localhost and connection shows up perfectly as before, full info.

[2] 2nd Problem - Out of no where, 6 hours after UPS identified and connected to FreeNAS I get 'UPS driver' messages:
Code:
Oct 11 22:24:02 freenas nutdrv_qx[16013]: Permissions problem: Input/output error
Oct 11 22:24:02 freenas upsd[16015]: Can't connect to UPS [ups] (nutdrv_qx-ups): No such file or directory
Oct 11 22:24:04 freenas upsmon[16040]: Poll UPS [ups] failed - Driver not connected
Oct 11 22:24:04 freenas upsmon[16040]: Communications with UPS ups lost
Oct 11 22:24:09 freenas upsmon[16040]: Poll UPS [ups] failed - Driver not connected
Oct 11 22:24:44 freenas last message repeated 7 times
Oct 11 22:26:49 freenas last message repeated 25 times


Following another post here, I've executed the following commands to debug:

Code:
[SOMEUSER@freenas] /# cat /etc/local/nut/ups.conf
[ups]
    driver = nutdrv_qx
    port = /dev/ugen0.4
    desc = "UPS"
novendor
port=auto
pollinterval=10


Switch off the UPS service in the GUI Run: /usr/local/libexec/nut/nutdrv_qx -a ups -DDD:

Code:
[SOMEUSER@freenas] /# /usr/local/libexec/nut/nutdrv_qx -a ups -DDD
Network UPS Tools - Generic Q* USB/Serial driver 0.01 (2.7.1)
USB communication driver 0.32
   0.000000     debug level is '3'
   0.004735     upsdrv_initups...
   0.009513     Checking device (05DC/A209) (/dev/usb//dev/ugen1.4)
   0.027528     - VendorID: 05dc
   0.027740     - ProductID: a209
   0.027784     - Manufacturer: Lexar
   0.027825     - Product: USB Flash Drive
   0.027865     - Serial Number: BBFD46CA080A8A449FA3
   0.027905     - Bus: /dev/usb
   0.027912     Trying to match device
   0.027989     Device does not match - skipping
   0.028291     Checking device (0665/5161) (/dev/usb//dev/ugen0.4)
   0.029974     - VendorID: 0665
   0.030022     - ProductID: 5161
   0.030062     - Manufacturer: unknown
   0.030103     - Product: unknown
   0.030109     - Serial Number: unknown
   0.030150     - Bus: /dev/usb
   0.030190     Trying to match device
   0.030232     Device matches
   0.061155     send: QGS
   0.205178     read: QGS
   0.205348     qx_process_answer: short reply (input.voltage)
   0.206404     send: QGS
   0.350115     read: QGS
   0.350202     qx_process_answer: short reply (input.voltage)
   0.350955     send: QGS
   0.495090     read: QGS
   0.495178     qx_process_answer: short reply (input.voltage)
   0.496142     send: QS
   0.813007     read: (234.9 234.9 234.9 002 50.0 13.7 --.- 00001001
   0.813347     Using protocol: Mustek 0.01
   0.813515     blazer_initups: skipping device.mfr
   0.813684     blazer_initups: skipping device.model
   0.813769     blazer_initups: skipping ups.firmware
   0.813985     upsdrv_initinfo...
   0.814737     send: QS
   1.131015     read: (234.9 234.9 234.9 002 50.0 13.7 --.- 00001001
   1.131688     ups_infoval_set: non numerical value [ups.temperature: --.-]
   1.132920     send: F
   1.340034     read: #230.0 003 12.00 50.0
   1.340841     No values for battery high/low voltages
   1.340967     Using 'guesstimation' (low: 10.400000, high: 13.000000)!
   1.341050     Battery runtime will not be calculated (runtimecal not set)
   1.341259     upsdrv_updateinfo...
   1.341348     Quick update...
   1.342400     send: QS
   1.659058     read: (234.9 234.9 234.9 002 50.0 13.7 --.- 00001001
   1.660571     dstate_init: sock /var/db/nut/nutdrv_qx-ups open on fd 6
   1.660744     upsdrv_updateinfo...
   1.660789     Quick update...
   1.661591     send: QS
   1.978029     read: (237.0 234.9 234.9 002 50.0 13.7 --.- 00001001
  11.661718     upsdrv_updateinfo...
  11.661886     Quick update...
  11.662851     send: QS
  11.978821     read: (234.9 232.8 234.9 002 50.0 13.7 --.- 00001001
etc...


Next /usr/local/libexec/nut/upsdrvctl start:

Code:
[SOMEUSER@freenas] /# /usr/local/libexec/nut/upsdrvctl start
Network UPS Tools - UPS driver controller 2.7.1
Network UPS Tools - Generic Q* USB/Serial driver 0.01 (2.7.1)
USB communication driver 0.32
Using protocol: Mustek 0.01
No values for battery high/low voltages
Using 'guesstimation' (low: 10.400000, high: 13.000000)!
Battery runtime will not be calculated (runtimecal not set)


and upsd -DDD:

Code:
[SOMEUSER@freenas] /# upsd -DDD
Network UPS Tools upsd 2.7.1
   0.000000     fopen /var/db/nut/upsd.pid: No such file or directory
   0.003680     listen_add: added 127.0.0.1:3493
   0.006383     setuptcp: try to bind to 127.0.0.1 port 3493
   0.007101     listening on 127.0.0.1 port 3493
   0.010021     Connected to UPS [ups]: nutdrv_qx-ups
   0.019816     user_add_action: adding 'login' for upsmon
   0.020153     user_add_action: adding 'master' for upsmon
   0.020368     user_add_action: adding 'fsd' for upsmon
   0.020702     mainloop: polling 2 filedescriptors
   0.021592     mainloop: polling 2 filedescriptors
   0.022737     mainloop: polling 2 filedescriptors
   0.023749     UPS [ups]: dump is done
   0.024046     mainloop: polling 2 filedescriptors
   2.025156     mainloop: no data available
   2.025666     mainloop: polling 2 filedescriptors
   4.026161     mainloop: no data available
   4.026706     mainloop: polling 2 filedescriptors
   6.027372     mainloop: no data available
   6.028683     Pinging UPS [ups]
   6.029824     mainloop: polling 2 filedescriptors
   6.030583     Got PONG from UPS [ups]
   6.031175     mainloop: polling 2 filedescriptors
   8.032259     mainloop: no data available
   8.033443     mainloop: polling 2 filedescriptors
  10.034155     mainloop: no data available
  10.034701     mainloop: polling 2 filedescriptors
  12.035179     mainloop: no data available
  12.035693     Pinging UPS [ups]
  12.036155     mainloop: polling 2 filedescriptors
  12.036489     Got PONG from UPS [ups]
  12.036705     mainloop: polling 2 filedescriptors
  14.037153     mainloop: no data available
  14.037703     mainloop: polling 2 filedescriptors
  16.038307     mainloop: no data available
  16.039534     mainloop: polling 2 filedescriptors
  18.041389     mainloop: no data available
  18.042615     Pinging UPS [ups]
  18.043715     mainloop: polling 2 filedescriptors
  18.044475     Got PONG from UPS [ups]
  18.044982     mainloop: polling 2 filedescriptors
  20.046167     mainloop: no data available
  20.046422     mainloop: polling 2 filedescriptors


Any help regarding these 2 issues will be highly appreciated !

Thanks

P.S (if it's any help):
Running FreeNAS-9.2.1.8-RELEASE-x64 on Intel(R) Pentium(R) CPU G3240 @ 3.10GHz with 8gb ram.
 

deed

Cadet
Joined
Oct 11, 2014
Messages
7
Not directly.

I've applied a workaround found in another post here in the forum;

Created a cronjob which runs every 3 minutes and executes the following script

Code:
#!/bin/sh
# Simple script which restarts NUT if the nutdrv_qx driver has stopped
CHECK=$0
DRIVER=nutdrv_qx
DATE=`date +"%Y-%m-%d %H:%M:%S"`
STATUSLOG=/var/log/ups-check.log
RESTARTLOG=/mnt/vol1/scripts/ups/ups-restart.log
OUTPUT=$(ps ax | grep -v grep | grep -v $CHECK | grep -c $DRIVER)
if [ "$OUTPUT" -gt "0" ]; then
   if [ -e $STATUSLOG ]; then
      echo "$DATE: $DRIVER driver found" >> $STATUSLOG
   fi
else
   if [ -e $STATUSLOG ]; then
      echo "$DATE: $DRIVER driver not found - restarting nut now" >> $STATUSLOG
   fi
   echo "$DATE: Restarting nut (because UPS driver has stopped)" >> $RESTARTLOG
   /usr/local/etc/rc.d/nut restart
fi


My UPS connection is still getting lost every now and then but the script puts it back on track.

I would be very happy to know that there's another/better solution.

Thanks
 
Status
Not open for further replies.
Top