Probleme mit Intranator und USV

[moczala]

Guten Tag,

am vergangenen Samstag hatten wir im Betrieb gegen 11 Uhr einen Stromausfall. Der Intranator hat ordnungsgemäß auf USV-Betrieb umgeschaltet. Obwohl der Stromaufall um 11:30 Uhr behoben war, wurde der Intranator um 11:48 Uhr heruntergefahren und blieb ausgeschaltet. Er musste heute morgen manuell gestartet werden.

Der Intranator wird an einer APC Smart-UPS 750 via USB betrieben. Die EInstellungen sind Standard: USV nach Herunterfahren abschalten. Minimaler Ladezustand vor Wiedereinschalten 15 %. Die USV hatte heute morgen 100 % Ladezustand.

Der Strom war definitiv wieder da, da mein Server an einer anderen USV korrekt wieder gestartet wurde. Beide Geräte hängen an der gleichen Sicherung.

Hat jemand dafür eine Erklärung?

Viele Grüße
Stefan Moczala-Geppert

[Thomas Jarosch]

Hallo Herr Moczala-Geppert,

vielleicht hat die Kommunikation mit der USV nicht mehr funktioniert. Durchsuchen Sie ihre "messages" Logdatei nach dem Schlagwort "ups". Die Meldungen sehen in etwa so aus:

Jul 18 19:07:53 intranator upsmon[1945]: UPS apcsmart@172.16.10.1 on battery
Jul 18 19:08:03 intranator upsmon[1945]: UPS apcsmart@172.16.10.1 on line power
Jul 19 15:17:47 intranator upsmon[1945]: Poll UPS [apcsmart@172.16.10.1] failed - Data stale
Jul 19 15:17:47 intranator upsmon[1945]: Communications with UPS apcsmart@172.16.10.1 lost
Jul 19 15:17:52 intranator upsmon[1945]: Poll UPS [apcsmart@172.16.10.1] failed - Data stale
Jul 19 15:17:57 intranator upsmon[1945]: Communications with UPS apcsmart@172.16.10.1 established

Herzliche Grüsse,
Thomas Jarosch

[moczala]

Hallo Herr Jarosch,

das sieht mir nicht so aus. Ich denke, die Kommunikation hat funktioniert. Ich habe die betreffenden Auszüge aus der log-Datei aufgelistet, vielleicht finden Sie da etwas.

Viele Grüße
Stefan Moczala-Geppert


Jul 19 11:01:02 intranator upsmon[1774]: UPS ups@127.0.0.1 on battery
...
Jul 19 11:13:52 intranator kernel: hiddev96: USB HID v1.10 Device [American Power Conversion Smart-UPS 750 FW:651.13.I USB FW:7.3] on usb-0000:00:1d.2-1
Jul 19 11:16:55 intranator kernel: hub 3-0:1.0: port 1 disabled by hub (EMI?), re-enabling...
Jul 19 11:16:55 intranator kernel: usb 3-1: USB disconnect, address 4
Jul 19 11:16:55 intranator kernel: usb 3-1: new low speed USB device using uhci_hcd and address 5
Jul 19 11:16:56 intranator kernel: usb 3-1: configuration #1 chosen from 1 choice
Jul 19 11:16:58 intranator kernel: hiddev96: USB HID v1.10 Device [American Power Conversion Smart-UPS 750 FW:651.13.I USB FW:7.3] on usb-0000:00:1d.2-1
Jul 19 11:16:58 intranator upsd[1763]: Data for UPS [ups] is stale - check driver
Jul 19 11:17:01 intranator upsd[1763]: UPS [ups] data is no longer stale
....
Jul 19 11:47:42 intranator upsmon[1774]: UPS ups@127.0.0.1 battery is low
Jul 19 11:47:42 intranator upsd[1763]: Client nutadmin@127.0.0.1 set FSD on UPS [ups]
Jul 19 11:47:43 intranator upsmon[1774]: Executing automatic power-fail shutdown
Jul 19 11:47:43 intranator upsmon[1774]: Auto logout and shutdown proceeding
Jul 19 11:47:47 intranator upsd[1763]: Host 127.0.0.1 disconnected (read failure)
Jul 19 11:47:48 intranator kernel: c2faxrecv[2550]: segfault at 05398808 eip 08068949 esp bfb0efdd error 4
Jul 19 11:47:48 intranator kernel: signal 11 sent to c2faxrecv[2550] uid:0, parent init[1] uid:0 by c2faxrecv[2550] uid:0, parent init[1] uid:0
Jul 19 11:47:48 intranator kernel: c2faxrecv[2555]: segfault at 05398808 eip 08068949 esp befff91d error 4
Jul 19 11:47:48 intranator kernel: signal 11 sent to c2faxrecv[2555] uid:0, parent c2faxrecv[2552] uid:0 by c2faxrecv[2555] uid:0, parent c2faxrecv[2552] uid:0
Jul 19 11:47:48 intranator kernel: c2faxrecv[2556]: segfault at 05398808 eip 08068949 esp bedff91d error 4
Jul 19 11:47:48 intranator kernel: signal 11 sent to c2faxrecv[2556] uid:0, parent c2faxrecv[2552] uid:0 by c2faxrecv[2556] uid:0, parent c2faxrecv[2552] uid:0
Jul 19 11:47:49 intranator mon[2509]: caught TERM signal, exiting
Jul 19 11:47:49 intranator mon: mon shutdown succeeded
Jul 19 11:47:49 intranator setsid: Stopping arnied services:
Jul 19 11:47:49 intranator pppd[3602]: Terminating on signal 15
Jul 19 11:47:49 intranator pppd[3602]: Exit.
Jul 19 11:47:49 intranator connectscripts[3596]: pppdial: pppd exited with 5
Jul 19 11:47:52 intranator setsid:
Jul 19 11:47:52 intranator rc: Stopping arnied succeeded
Jul 19 11:47:52 intranator setsid: Stopping dialout...
Jul 19 11:47:52 intranator setsid: command error (
Jul 19 11:47:53 intranator setsid: client connection-error): -1: write failed: connection already closed
Jul 19 11:47:53 intranator setsid: command error (client connection-error): -1: write failed: connection already closed
Jul 19 11:47:53 intranator setsid: command error (client connection-error): -1: write failed: connection already closed
Jul 19 11:47:53 intranator setsid:
Jul 19 11:47:53 intranator rc: Stopping dialout succeeded
Jul 19 11:47:53 intranator setsid: Stopping dialin...
Jul 19 11:47:53 intranator setsid:
Jul 19 11:47:53 intranator rc: Stopping dialin succeeded
Jul 19 11:47:53 intranator FaxQueuer[2317]: QUIT
Jul 19 11:47:53 intranator hylafax: hfaxd shutdown succeeded
Jul 19 11:47:53 intranator rc: Stopping keytable succeeded
Jul 19 11:47:53 intranator httpd: httpd shutdown succeeded
Jul 19 11:47:53 intranator setsid: Stopping squid:
Jul 19 11:47:54 intranator squid[2098]: Squid Parent: child process 2101 exited with status 0
Jul 19 11:47:55 intranator setsid: .
Jul 19 11:47:55 intranator setsid:
Jul 19 11:47:55 intranator rc: Stopping squid succeeded
Jul 19 11:47:55 intranator sshd: sshd -TERM succeeded
Jul 19 11:47:56 intranator sshd[1858]: Received signal 15; terminating.
Jul 19 11:47:56 intranator setsid: Shutting down postfix:
Jul 19 11:47:56 intranator postfix: succeeded
Jul 19 11:47:56 intranator setsid: ^[[60G
Jul 19 11:47:56 intranator setsid:
Jul 19 11:47:56 intranator rc: Stopping postfix succeeded
Jul 19 11:47:56 intranator setsid: Stopping AMaViS email virus scanner (for Postfix):
Jul 19 11:47:58 intranator amavisd: succeeded
Jul 19 11:47:58 intranator setsid: ^[[60G
Jul 19 11:47:59 intranator setsid:
Jul 19 11:47:59 intranator rc: Stopping amavisd succeeded
Jul 19 11:47:59 intranator arnielizer: arnielizer shutdown succeeded
Jul 19 11:47:59 intranator master[1885]: exiting on SIGTERM/SIGINT
Jul 19 11:47:59 intranator cyrus-imapd: cyrus-master shutdown succeeded
Jul 19 11:47:59 intranator freebusyd: freebusyd shutdown succeeded
Jul 19 11:47:59 intranator info_mqueue_ui: info_mqueue_ui shutdown succeeded
Jul 19 11:47:59 intranator isdnlog: Got signal 15
Jul 19 11:47:59 intranator isdnlog: exit now 7
Jul 19 11:47:59 intranator isdnlog: File /var/run/isdnlog.isdnctrl.pid removed!
Jul 19 11:47:59 intranator isdnlog: File /var/lock/LCK..isdnctrl removed!
Jul 19 11:47:59 intranator isdn: isdnlog shutdown succeeded
Jul 19 11:48:00 intranator kernel: fcpci: Removing registered applications!
Jul 19 11:48:00 intranator kernel: kcapi: card [001] down.
Jul 19 11:48:00 intranator kernel: capidrv: controller 1 down
Jul 19 11:48:00 intranator kernel: capidrv-1: now down.
Jul 19 11:48:00 intranator kernel: fcpci: Removing...
Jul 19 11:48:00 intranator kernel: kcapi: Controller [001]: fcpci-4800-20 unregistered
Jul 19 11:48:00 intranator kernel: fcpci: Removed.
Jul 19 11:48:00 intranator kernel: fcpci: Driver 'fcpci' detached
Jul 19 11:48:00 intranator kernel: capi: Rev 1.1.2.7: unloaded
Jul 19 11:48:00 intranator kernel: capidrv: Rev 1.1.2.2 : unloaded
Jul 19 11:48:00 intranator kernel: ISDN-subsystem unloaded
Jul 19 11:48:00 intranator mdmonitor: mdadm shutdown succeeded
Jul 19 11:48:01 intranator smb: smbd shutdown succeeded
Jul 19 11:48:01 intranator nmbd[2210]: [2008/07/19 11:48:01, 0] nmbd/nmbd.c:terminate(58)
Jul 19 11:48:01 intranator nmbd[2210]: Got SIGTERM: going down...
Jul 19 11:48:01 intranator smb: nmbd shutdown succeeded
Jul 19 11:48:02 intranator named[1848]: shutting down: flushing changes
Jul 19 11:48:02 intranator named[1848]: stopping command channel on 127.0.0.1#953
Jul 19 11:48:02 intranator named[1848]: no longer listening on 127.0.0.1#53
Jul 19 11:48:02 intranator named[1848]: no longer listening on 192.168.0.1#53
Jul 19 11:48:02 intranator named: succeeded
Jul 19 11:48:02 intranator named[1848]: exiting
Jul 19 11:48:02 intranator crond: crond shutdown succeeded
Jul 19 11:48:02 intranator ntpd[1246]: Terminating
Jul 19 11:48:02 intranator ntpd: ntpd shutdown succeeded
Jul 19 11:48:02 intranator dd: 1+0 records in
Jul 19 11:48:02 intranator dd: 1+0 records out
Jul 19 11:48:02 intranator random: Saving random seed succeeded
Jul 19 11:48:02 intranator setsid: Stopping F-Secure AntiVirus:
Jul 19 11:48:02 intranator fsavd: succeeded
Jul 19 11:48:03 intranator setsid: ^[[60G
Jul 19 11:48:03 intranator setsid:
Jul 19 11:48:03 intranator rc: Stopping fsavd succeeded
Jul 19 11:48:03 intranator upsmon: Network UPS Tools upsmon 2.2.2
Jul 19 11:48:03 intranator upsmon: kill: No such process
Jul 19 11:48:03 intranator upsmon: NUT Stopping UPS monitor: succeeded
Jul 19 11:48:03 intranator network: Shutting down interface eth0 succeeded
Jul 19 11:48:03 intranator network: Shutting down interface eth1 succeeded
Jul 19 11:48:03 intranator sysctl: net.ipv4.ip_forward = 0
Jul 19 11:48:03 intranator network: Disabling IPv4 packet forwarding succeeded
Jul 19 11:48:03 intranator upsd[1763]: Signal 15: exiting
Jul 19 11:48:03 intranator upsd: Network UPS Tools upsd 2.2.2
Jul 19 11:48:03 intranator upsd: NUT Stopping UPS daemon succeeded
Jul 19 11:48:03 intranator usbhid-ups[1755]: Signal 15: exiting
Jul 19 11:48:03 intranator upsdrvctl: Network UPS Tools - UPS driver controller 2.2.2
Jul 19 11:48:03 intranator upsd: NUT Stopping UPS model drivers succeeded
Jul 19 11:48:03 intranator setsid: Flushing firewall rules:
Jul 19 11:48:04 intranator iptables: succeeded
Jul 19 11:48:04 intranator setsid: ^[[60G
Jul 19 11:48:04 intranator iptables: succeeded
Jul 19 11:48:04 intranator setsid:
Jul 19 11:48:04 intranator setsid: Setting chains to ACCEPT policy:
Jul 19 11:48:04 intranator setsid:
Jul 19 11:48:04 intranator setsid: Unloading iptables modules:
Jul 19 11:48:04 intranator iptables: succeeded
Jul 19 11:48:04 intranator setsid: ^[[60G
Jul 19 11:48:04 intranator setsid:
Jul 19 11:48:04 intranator rc: Stopping iptables succeeded
Jul 19 11:48:04 intranator kernel: Kernel logging (proc) stopped.
Jul 19 11:48:04 intranator kernel: Kernel log daemon terminating.
Jul 19 11:48:05 intranator syslog: klogd shutdown succeeded
Jul 19 11:48:05 intranator exiting on signal 15
Jul 21 07:16:15 intranator syslogd 1.5.0: restart.

[Thomas Jarosch]

Hallo Herr Moczala-Geppert,

Zitat von moczala

Jul 19 11:16:58 intranator upsd[1763]: Data for UPS [ups] is stale - check driver
Jul 19 11:17:01 intranator upsd[1763]: UPS [ups] data is no longer stale
....
Jul 19 11:47:42 intranator upsmon[1774]: UPS ups@127.0.0.1 battery is low
Jul 19 11:47:42 intranator upsd[1763]: Client nutadmin@127.0.0.1 set FSD on UPS [ups]
Jul 19 11:47:43 intranator upsmon[1774]: Executing automatic power-fail shutdown

Ok, die Batterie der USV ist auf "low" gegangen. In diesem Zustand fahren sich alle Server automatisch herunter. Ist das BIOS Ihres Intranators so eingestellt, daß es sich automatisch bei Stromzufuhr wieder eingeschaltet?
Die Standardkonfiguration ist eigentlich "last-state", welche bei einem sauberen Herunterfahren wie hier "ausgeschaltet" ist.

Herzliche Grüsse,
Thomas Jarosch

[moczala]

Hallo Herr Jarosch,

bzgl. des BIOS müsste ich nachsehen. Da ich dazu die Maschine herunterfahren muss, geht das erst später. Es handelt sich nicht um eine Intranator Appliance sondern um einen handelsüblichen Fujitsu-Siemens-Rechner.

Merkwürdig finde ich, dass der Intranator auf Battery-low der USV reagiert (11:47), obwohl die normale Stromversorgung schon wieder hergestellt wurde (11:30).

Viele Grüße
Stefan Moczala-Geppert

[Thomas Jarosch]

Zitat von moczala

Merkwürdig finde ich, dass der Intranator auf Battery-low der USV reagiert (11:47), obwohl die normale Stromversorgung schon wieder hergestellt wurde (11:30).

Der Intranator beachtet nur den Batteriezustand, da die Stromversorgung ständig an und ausgehen könnte und somit kein stabiler Betrieb gewährleistet ist. Sobald eine USV auf "low" geht ist der Akku so gut wie alle. Hier ist Herunterfahren die sinnvollste Option, um Ihre Daten zu schützen.

Herzliche Grüsse,
Thomas Jarosch

[moczala]

Hallo Herr Jarosch,

mangels Zeit bin ich erst jetzt dazu gekommen, das BIOS zu prüfen.

Die Standardkonfiguration ist eigentlich "last-state", welche bei einem sauberen Herunterfahren wie hier "ausgeschaltet" ist.

In der Tat war das der Fall. Eigentlich unglücklich als default-Einstellung für einen Server , aber egal - jetzt steht der Wert auf "always on" und damit sollte das Problem hoffentlich gelöst sein.

Vielen Dank für Ihre Hilfe
Stefan Moczala-Geppert