Nut upsdev - Jan 2012 - bestfortress driver establishes/loses/establishes communication and so on...

[As posted as Ubuntu Question #184284 on Launchpad]

Hi, I try to set up nut (2.4.3) on my Lucid (10.04.3 LTS) to make use of 
my old but very trusty UPS (Best Power Fortress 660 LI).

Yes, this UPS is old (about 16 years), but with its third battery pack 
last week it is as good as new. It runs perfectly well with Windows XP, 
Vista and even Windows 7. But not so with Ubuntu and nut.

After several hurdles I managed to get nut start flawlessly (although I 
always have to do upsdrvctl start und /etc/init.d/nut start manually, 
but that is just another [reported] bug, upstart doesn't start some 
daemons). Btw., the last hurdle was that nutmon did not want to start 
without its own user, nutmon, which was not setup by the package.

The problem is that soon after nut started successfully, communication 
to the UPS is lost, with "data stale". After some minutes,
communication
gets re-established. Then lost again and so on and on and on...

When communication is reported established, upsc fortress gives me a 
comple list of values that tell me that upsmon really talked to the 
device (although high and low transition are always missing?).

As this is nut 2, fortress-drivers are set back to being experimental, I 
know, but I do have a Fortress so I have to use these drivers (0.02 - 
2.4.3). The Fortress is set to use advanced communication mode 4, which 
means "real" cable 95B and 9600 bits per second on /dev/ttyS0. I have 
told the driver so (adding baudrate=9600 to /etc/nut/ups.conf) and the 
fact that sometimes comm is established tells me its not a speed issue.

It also isn't a load issue - this is an Intel Quadcore machine, 9600 bps 
of serial communication should not be an issue. I did experiment with 
pollintervall, maxage, pollfreq and so on - doesn change anything, only 
the amount of time between the glitches. The windows app (Checkups II) 
polls the UPS even more often, seemingly once per second, so 
communication "overload" on the UPS part can also be ruled out.

In the meantime I have done some debugging with even higher debug levels 
(up to 6 seem to be supported). With -DDDD it seems like the driver does 
not poll in the intervall specified. After communication is established, 
and all data from within the UPS are present in the debug output, the 
USV data is immediately marked stale. One would tend to believe that 
after a successful poll of UPS data the stale declaration could only 
come after one intervall has elapsed, but it comes at once. After that 
there is silence. No more debug output from the driver. Not one single 
line of debug output.

But the driver isn't dead. It's still running, and occasionally it does 
re-establish communication with the UPS and delivers some data. But no 
debug output...

Thanks for your help.
Oliver

Hi Oliver,

2012/1/18 Oliver Kluge <ok23 at kluge-digital.de>:
> [As posted as Ubuntu Question #184284 on Launchpad]
I missed this, though the right # is 184824 ;-)
> Hi, I try to set up nut (2.4.3) on my Lucid (10.04.3 LTS) to make use of my
> old but very trusty UPS (Best Power Fortress 660 LI).
>
> Yes, this UPS is old (about 16 years), but with its third battery pack last
> week it is as good as new. It runs perfectly well with Windows XP, Vista
and
> even Windows 7. But not so with Ubuntu and nut.
old doesn't mean not useful, for sure ;-)
the only thing that has improved there is efficiency...
> After several hurdles I managed to get nut start flawlessly (although I
> always have to do upsdrvctl start und /etc/init.d/nut start manually, but
> that is just another [reported] bug, upstart doesn't start some
daemons).
> Btw., the last hurdle was that nutmon did not want to start without its own
> user, nutmon, which was not setup by the package.
I really have to have a closer look there.
I'm suspecting some race condition between upstart, sysV compat layer,
udev and NUT starting, which could result in this.
> The problem is that soon after nut started successfully, communication to
> the UPS is lost, with "data stale". After some minutes,
communication gets
> re-established. Then lost again and so on and on and on...
>
> When communication is reported established, upsc fortress gives me a comple
> list of values that tell me that upsmon really talked to the device
> (although high and low transition are always missing?).
>
> As this is nut 2, fortress-drivers are set back to being experimental, I
> know, but I do have a Fortress so I have to use these drivers (0.02 -
> 2.4.3). The Fortress is set to use advanced communication mode 4, which
> means "real" cable 95B and 9600 bits per second on /dev/ttyS0. I
have told
> the driver so (adding baudrate=9600 to /etc/nut/ups.conf) and the fact that
> sometimes comm is established tells me its not a speed issue.
>
> It also isn't a load issue - this is an Intel Quadcore machine, 9600
bps of
> serial communication should not be an issue. I did experiment with
> pollintervall, maxage, pollfreq and so on - doesn change anything, only the
> amount of time between the glitches. The windows app (Checkups II) polls
the
> UPS even more often, seemingly once per second, so communication
"overload"
> on the UPS part can also be ruled out.
>
> In the meantime I have done some debugging with even higher debug levels
(up
> to 6 seem to be supported). With -DDDD it seems like the driver does not
> poll in the intervall specified. After communication is established, and
all
> data from within the UPS are present in the debug output, the USV data is
> immediately marked stale. One would tend to believe that after a successful
> poll of UPS data the stale declaration could only come after one intervall
> has elapsed, but it comes at once. After that there is silence. No more
> debug output from the driver. Not one single line of debug output.
>
> But the driver isn't dead. It's still running, and occasionally it
does
> re-establish communication with the UPS and delivers some data. But no
debug
> output...
can you please send in the driver debug output (-DDDDD) in gzip'ed form?
let the driver run for a minute or so, then stop it using Ctrl+C

I will probably have to add more traces in the driver, to understand
what's going wrong.
Will you be ready to test the trunk, for hunting your issue?
AFAICT, the only thing that could generate this staleness the way you
see it, is a bad checksum.
we'll see...

cheers,
Arnaud
-- 
Linux / Unix Expert R&D - Eaton - http://powerquality.eaton.com
Network UPS Tools (NUT) Project Leader - http://www.networkupstools.org/
Debian Developer - http://www.debian.org
Free Software Developer - http://arnaud.quette.free.fr/

Hi, this is the driver output with -DDDD (5).

This is all. After the final line no more output from the driver at all, 
just the regular status broadcasts from upsmon. But the driver process 
is still up and running, as the occasional changes in staleness show. 
But no more debug output.

Thanks
Oliver

/lib/nut/bestfortress -a fortress -DDDDD
Network UPS Tools - Best Fortress UPS driver 0.02 (2.4.3)
Warning: This is an experimental driver.
Some features may not function correctly.

    0.000000	debug level is '5'
    0.000658	send_to_all: SETINFO device.type "ups"
    0.000672	send_to_all: SETINFO driver.version "2.4.3"
    0.000681	send_to_all: SETINFO driver.version.internal "0.02"
    0.000689	send_to_all: SETINFO driver.name "bestfortress"
    0.000698	send_to_all: SETINFO ups.mfr "Best Power"
    0.000706	send_to_all: SETINFO ups.model "Fortress"
    0.000714	send_to_all: SETINFO battery.voltage.nominal "24"
    0.000723	send_to_all: SETINFO ups.load "0"
    0.000731	send_to_all: SETINFO output.voltamps "0"
    0.000739	send_to_all: SETINFO ups.delay.shutdown "10"
    0.000748	send_to_all: SETINFO input.transfer.low ""
    0.000756	send_to_all: SETFLAGS input.transfer.low RW STRING
    0.000764	send_to_all: SETAUX input.transfer.low 3
    0.000772	send_to_all: SETINFO input.transfer.high ""
    0.000781	send_to_all: SETFLAGS input.transfer.high RW STRING
    0.000788	send_to_all: SETAUX input.transfer.high 3
    0.000796	send_to_all: SETINFO battery.runtime.low ""
    0.000804	send_to_all: SETFLAGS battery.runtime.low RW STRING
    0.000812	send_to_all: SETAUX battery.runtime.low 3
    0.000819	send_to_all: ADDCMD shutdown.return
    0.000827	send_to_all: ADDCMD load.off
   11.004290	dstate_init: sock /var/run/nut/bestfortress-fortress open 
on fd 5
   11.004318	send_to_all: SETINFO driver.parameter.pollinterval "2"
   11.004329	send_to_all: SETINFO device.mfr "Best Power"
   11.004339	send_to_all: SETINFO device.model "Fortress"
 

Broadcast Message from nutmon at FSC 

         (somewhere) at 0:34 ... 

 

Communications with UPS fortress at localhost established 

 

   22.007988	new connection on fd 6
   33.011966	send_to_one: DATASTALE
   33.011997	send_to_one: SETINFO battery.runtime.low ""
   33.012015	send_to_one: SETAUX battery.runtime.low 3
   33.012026	send_to_one: SETFLAGS battery.runtime.low RW STRING
   33.012036	send_to_one: SETINFO battery.voltage.nominal "24"
   33.012047	send_to_one: SETINFO device.mfr "Best Power"
   33.012057	send_to_one: SETINFO device.model "Fortress"
   33.012067	send_to_one: SETINFO device.type "ups"
   33.012077	send_to_one: SETINFO driver.name "bestfortress"
   33.012087	send_to_one: SETINFO driver.parameter.baudrate "9600"
   33.012096	send_to_one: SETINFO driver.parameter.max_load "660"
   33.012107	send_to_one: SETINFO driver.parameter.pollinterval "2"
   33.012117	send_to_one: SETINFO driver.parameter.port "/dev/ttyS0"
   33.012127	send_to_one: SETINFO driver.version "2.4.3"
   33.012136	send_to_one: SETINFO driver.version.internal "0.02"
   33.012147	send_to_one: SETINFO input.transfer.high ""
   33.012156	send_to_one: SETAUX input.transfer.high 3
   33.012166	send_to_one: SETFLAGS input.transfer.high RW STRING
   33.012177	send_to_one: SETINFO input.transfer.low ""
   33.012190	send_to_one: SETAUX input.transfer.low 3
   33.012200	send_to_one: SETFLAGS input.transfer.low RW STRING
   33.012210	send_to_one: SETINFO output.voltamps "0"
   33.012219	send_to_one: SETINFO ups.delay.shutdown "10"
   33.012229	send_to_one: SETINFO ups.load "0"
   33.012239	send_to_one: SETINFO ups.mfr "Best Power"
   33.012248	send_to_one: SETINFO ups.model "Fortress"
   33.012258	send_to_one: ADDCMD load.off
   33.012267	send_to_one: ADDCMD shutdown.return
   33.012277	send_to_one: DUMPDONE
   33.012289	send_to_one: PONG
 

Broadcast Message from nutmon at FSC 

         (somewhere) at 0:35 ... 

 

Communications with UPS fortress at localhost lost

2012/1/24 Oliver Kluge <ok23 at kluge-digital.de>:
> Hi, this is the driver output with -DDDD (5).
Hi
> This is all. After the final line no more output from the driver at all,
> just the regular status broadcasts from upsmon. But the driver process is
> still up and running, as the occasional changes in staleness show. But no
> more debug output.
> (...)
nothing but normal, since this driver was lacking debug traces.
This is what I added in the current development version.
Could you please try this and report again the traces?

Use the following procedure to do so:
$ svn co svn://anonscm.debian.org/nut/trunk
$ cd trunk
$ ./autogen.sh
$ ./configure --sysconfdir=/etc/nut --with-statepath=/var/run/nut
--with-altpidpath=/var/run/nut --with-drvpath=/lib/nut
--with-pidpath=/var/run/nut --datadir=/usr/share/nut
--with-pkgconfig-dir=/usr/lib/pkgconfig --with-user=nut
--with-group=nut
$ make
$ sudo ./drivers/bestfortress -a fortress -DDDDD

cheers,
Arnaud
-- 
Linux / Unix Expert R&D - Eaton - http://powerquality.eaton.com
Network UPS Tools (NUT) Project Leader - http://www.networkupstools.org/
Debian Developer - http://www.debian.org
Free Software Developer - http://arnaud.quette.free.fr/

Long ago, Nostradamus foresaw that on 01/24/2012 03:25 AM, Arnaud Quette 
would write:
> Use the following procedure to do so: 
$ svn co svn://anonscm.debian.org/nut/trunk
$ cd trunk
$ ./autogen.sh
$ ./configure --sysconfdir=/etc/nut --with-statepath=/var/run/nut
--with-altpidpath=/var/run/nut --with-drvpath=/lib/nut
--with-pidpath=/var/run/nut --datadir=/usr/share/nut
--with-pkgconfig-dir=/usr/lib/pkgconfig --with-user=nut
--with-group=nut
$ make
$ sudo ./drivers/bestfortress -a fortress -DDDDD


-------------- next part --------------
An embedded and charset-unspecified text was scrubbed...
Name: fortress.txt
URL:
<http://lists.alioth.debian.org/pipermail/nut-upsdev/attachments/20120125/de229f23/attachment.txt>

Hi,

Stuart D. Gathman wrote:
> There is no handshake. The record length is 80 bytes. The UPS does not
> send the 80 byte record until you ask it to. So you just need a buffer
> with 81 bytes for the data. The COM driver is returning too soon, and
> doesn't
> have a big enough buffer.
Well, I never see any communicaation with 80 bytes. And upsc fortress 
does give correct looking information once communication is established.

Oliver