Homeserver Forum

Hallo zusammen,

seit heute morgen habe ich an einigen Clients ein komisches Problem. Der WHS läuft anscheinend einwandfrei, aber auf einigen Clients bleiben das Connector-Icon und das Ligths-Out Icon ohne Verbindung. Auf der Console werden die Computer als nicht verbunden angezeigt.

Was habe ich versucht:

1. Server neugestartet
2. Auf einem Client Lights-Out Neu installiert / Auf dem Server 1.5.1.1572 installiert.
3. Lights-Out Dienst auf dem Client beendet und den WHS-Connector gestartet. (War beendet!?)

Damit ist es mir gelungen, den Computer wieder in der Console als verbunden zu sehen. Wenn man aber den Lights-out Dienst startet, wird der Connector sofort wieder beendet und der Server geht nach der eingestellten Zeit in den Standby. Anbei mal das Log für so einen Start des Lights-Out Dienstes.

2011-10-29 14:50:36:500 [ 7] DEBUG ReadNextBackupTimeFromRegistryV1: Start changed from 30.10.2011 02:32:06 to 30.10.2011 02:19:12, Window end 5
2011-10-29 14:50:36:500 [ 7] DEBUG ClientConfig: NextBackupTime changed to 30.10.2011 02:19:12
2011-10-29 14:50:36:500 [ 7] DEBUG PropertyChanged: NextBackupTime
2011-10-29 14:50:36:500 [ 7] DEBUG SendTransportCommandWithParams NextScheduledBackup 634555379524569483 [result False]
2011-10-29 14:50:36:500 [ 7] DEBUG Sending next backup time [result False]
2011-10-29 14:50:36:500 [ 7] DEBUG SetWhsBackupTime to 04:45 [was 02:19] because LO backup at 03:32 is in backup window 2 - 5
2011-10-29 14:50:36:500 [ 7] DEBUG KickConnector: Stopping WHS connector
2011-10-29 14:50:37:265 [ 8] DEBUG 101 Event Log Test successful
2011-10-29 14:50:38:640 [ 4] DEBUG PipeServer: Client has connected
2011-10-29 14:50:38:640 [ 8] DEBUG PipeServer: Read 0 bytes, already disposed=False
2011-10-29 14:50:40:078 [ 10] DEBUG Transport state changed, server False
2011-10-29 14:50:40:093 [ 10] DEBUG StateChanged: Transport is disconnected
2011-10-29 14:50:40:093 [ 10] DEBUG SERVER IS DOWN
2011-10-29 14:50:40:093 [ 11] DEBUG Transport closed
2011-10-29 14:50:40:093 [ 11] DEBUG TransportClient disposed...
2011-10-29 14:50:40:093 [ 11] DEBUG SERVER IS DOWN
2011-10-29 14:50:40:390 [ 4] DEBUG PipeServer: Client has connected
2011-10-29 14:50:45:078 [ 7] DEBUG KickConnector: Stopped WHS connector
2011-10-29 14:50:45:078 [ 7] DEBUG Saved next backup time to registry 30.10.2011 04:45:00
2011-10-29 14:50:48:078 [ 7] DEBUG -----------------------
2011-10-29 14:50:48:078 [ 7] DEBUG LightsOutClientService : 1.5.1.1555
2011-10-29 14:50:48:078 [ 7] DEBUG .NET Framework Version : 2.0.50727.3625
2011-10-29 14:50:48:078 [ 7] DEBUG Running on machine : ACERQ
2011-10-29 14:50:48:078 [ 7] DEBUG Operating System : Windows XP [Professional Service Pack 3], 5.1.2600.196608, CPU x86, OS x86, Program x86
2011-10-29 14:50:48:078 [ 7] DEBUG -----------------------
2011-10-29 14:50:48:109 [ 7] DEBUG SonicWALL Virtual Adapter: IP Address 223.1.1.128
2011-10-29 14:50:48:109 [ 7] DEBUG LAN-Verbindung: IP Address 192.168.201.108
2011-10-29 14:50:48:109 [ 7] DEBUG VMware Network Adapter VMnet1: IP Address 192.168.237.1
2011-10-29 14:50:48:109 [ 7] DEBUG VMware Network Adapter VMnet8: IP Address 192.168.18.1
2011-10-29 14:50:48:109 [ 7] DEBUG -----------------------
2011-10-29 14:50:48:109 [ 7] DEBUG SERVER IS : UNKNOWN
2011-10-29 14:50:48:109 [ 7] DEBUG Server MAC : 00-15-58-87-97-C5
2011-10-29 14:50:48:109 [ 7] DEBUG Automatic wake-up : True
2011-10-29 14:50:48:109 [ 7] DEBUG Allow server suspend : True
2011-10-29 14:50:48:109 [ 7] DEBUG Server controlled : True
2011-10-29 14:50:48:109 [ 7] DEBUG Domain Wake-On-Wan :
2011-10-29 14:50:48:109 [ 7] DEBUG Next backup time : 30.10.2011 02:19:12
2011-10-29 14:50:48:109 [ 7] DEBUG Next Lights-Out backup: 03:32:00
2011-10-29 14:50:48:109 [ 7] DEBUG Backup window start : 2
2011-10-29 14:50:48:109 [ 7] DEBUG Backup window end : 5
2011-10-29 14:50:48:109 [ 7] DEBUG Lights-Out wake-up : 03:30:00
2011-10-29 14:50:48:156 [ 7] DEBUG Suspend supported : True
2011-10-29 14:50:48:156 [ 7] DEBUG Hibernation supported: True
2011-10-29 14:50:48:156 [ 7] DEBUG -----------------------
2011-10-29 14:50:48:156 [ 7] DEBUG SendTransportCommandWithParams NextScheduledBackup 634555379524569483 [result False]
2011-10-29 14:50:48:156 [ 7] DEBUG Sending next backup time [result False]
2011-10-29 14:50:48:187 [ 7] DEBUG ClientConfig: Interval changed to 10
2011-10-29 14:50:48:187 [ 7] DEBUG PropertyChanged: Interval
2011-10-29 14:50:48:250 [ 7] DEBUG sending magic packet [00-15-58-87-97-C5] to 192.168.201.255:9
2011-10-29 14:50:48:265 [ 7] DEBUG sending magic packet [00-15-58-87-97-C5] to 192.168.201.255:9
2011-10-29 14:50:48:265 [ 7] DEBUG >> Sent WOL packet(s) to server with MAC 00-15-58-87-97-C5
2011-10-29 14:50:48:265 [ 7] DEBUG SetWhsBackupTime to 04:45 [was 02:19] because LO backup at 03:32 is in backup window 2 - 5
2011-10-29 14:50:48:265 [ 7] DEBUG KickConnector: Starting stopped (?) WHS connector
2011-10-29 14:50:48:296 [ 7] DEBUG KickConnector: Started WHS connector
2011-10-29 14:50:48:296 [ 7] DEBUG Saved next backup time to registry 30.10.2011 04:45:00
2011-10-29 14:50:51:296 [ 7] DEBUG ClientConfig: Interval changed to 5
2011-10-29 14:50:51:296 [ 7] DEBUG PropertyChanged: Interval
2011-10-29 14:50:51:296 [ 7] DEBUG ReadNextBackupTimeFromRegistryV1: Start changed from 30.10.2011 02:19:12 to 30.10.2011 02:07:48, Window end 5
2011-10-29 14:50:51:296 [ 7] DEBUG ClientConfig: NextBackupTime changed to 30.10.2011 02:07:48
2011-10-29 14:50:51:296 [ 7] DEBUG PropertyChanged: NextBackupTime
2011-10-29 14:50:51:296 [ 7] DEBUG SendTransportCommandWithParams NextScheduledBackup 634555372688831306 [result False]
2011-10-29 14:50:51:296 [ 7] DEBUG Sending next backup time [result False]
2011-10-29 14:50:51:296 [ 7] DEBUG SetWhsBackupTime to 04:45 [was 02:07] because LO backup at 03:32 is in backup window 2 - 5
2011-10-29 14:50:51:296 [ 7] DEBUG KickConnector: Stopping WHS connector
2011-10-29 14:50:58:468 [ 7] DEBUG KickConnector: Stopped WHS connector
2011-10-29 14:50:58:484 [ 7] DEBUG Saved next backup time to registry 30.10.2011 04:45:00
2011-10-29 14:50:58:484 [ 12] DEBUG > OnStop
2011-10-29 14:50:58:484 [ 12] DEBUG Broadcast: close all controllers
2011-10-29 14:50:58:484 [ 8] DEBUG PipeServer: Read 0 bytes, already disposed=True
2011-10-29 14:50:59:484 [ 12] DEBUG < Stopped

Die ganze Installation lief seit 324 Tagen einwandfrei. Auch wurde gestern Nichts bewußt geändert. Betroffen sind XP und W7 Computer.

Ich bin ziemlich ratlos, woran das liegen könnte. Jemand eine Idee?

Vielen Dank für jede Hilfe.

Agio

scheint kein Einzelfall zu sein: viewtopic.php?f=29&t=16250&p=120073#p120073

Da meldet sich mein Bauch: steuert LO die Sicherung über den Kalender? Morgen ist Sommerzeitende .. und der Kalender auf meinem iPAD hat anscheinend auch Problemem mit Terminen am 30.10.2011

Vielen Dank für den Link. Schön nicht allein mit dem Problem zu sein.

Die Idee mit der Zeitumstellung ist gut. Wäre ich nie drauf gekommen. Ich habe die Sicherungszeit zwischen 2:00 und 5.00 Uhr und
nur die Computer haben das Problem, die von Lights-Out zur Sicherungszeit geweckt werden sollen. Mal schauen wie es morgen früh
aussieht.

Gruss

Agio

Es hat eventuell wirklich etwas mit der Zeit zu tun, dann aber primär mit dem Connector. Lights-Out setzt die vom Connector verwendete nächste Backup-Zeit in der Registry. Damit der Connector diese übernimmt wird der beendet und startet sich dann selber wieder neu. Warum das jetzt ausgerechnet an diesem Tag schief geht ist mir unklar, es deutet aber alles auf ein Problem mit der Zeitumstellung in Windows hin.

Als erste Abhilfe sollte mal der Fehlerzähler in der Dienststeuerung für den Connector zurückgesetzt und dann der Connector händisch gestartet werden.

Gruß
Martin

@Martin:
Das Verhalten trat bei mir auf allen Systemen, die am 30. vor der Zeitumstellung gesichert wurden, auf und erst wieder nach Ende der Sommerzeit gesichert werden sollten.
Kann es sein, dass LO die nächste Sicherung mit 24 Stunden Differenz an den Connector übergibt, dieser die durch bevorstehende Umstellung um eine Stunde reduziert und LO widerum dann davon ausgeht, die Zeit wäre nicht aktualisiert worden? Deshalb übergibt er die Zeit wieder, stoppt und startet den Connector und prüft... usw.
Es fiel mir auf, dass der Dienst immer wieder gestartet und dann wieder gestoppt wurde. Die "Endlosschleife" ließe sich so erklären und sie tritt nur am Ende der Sommerzeit auf, wenn die Zeit um eine Stunde zurückgestellt wird. Insofern denke ich, dass das Problem vom LO Dienst ausgegangen ist.

VG
Matthias

Ich denke diese Analyse ist weitgehend zutreffend, danke. Lights-Out berechnet eine neue Sicherungszeit, die immer 15 Minuten vor Ende der nächsten Sicherungszeit liegt. Zur Übernahme wird der Connector nu gestartet, Dieser hat die dann ausserhalb liegende Zeit korrigiert, Lights-Out berechnet die Zeit neu usw.

Gruß
Martin

Hallo Martin,

seit gestern ist es wieder soweit, der LO-Dienst beendet den WHS Connector Dienst. Da wir kurz vor dem Jahreswechsel stehen und keine Zeitumstellung im Raume steht, scheint das Problem sich nicht nur auf die Sommer- und Winterzeit zu beziehen. Besteht noch eine Chance, dass diese Probleme gefixt werden?

An dieser Stelle sei es mir erlaubt: Ich wünsche allen einen guten Start ins Jahr 2012!

VG
Matthias

Hallo Martin,

dass muss ich leider bestätigen. Seit gestern klemmts auch bei mir auf mehreren Rechnern. Auch ich hoffe das die Probleme noch gefixt werden.

Auch von mir: einen guten Rutsch in neue Jahr.

Mit welcher Version ist das aufgetreten?

Gestern hat Microsoft zudem ein außerplanmäßiges Update für .Net Framework herausgegeben, vielleicht liegt es auch daran.

Schickt mir bitte die Clientlogs aus c:\programdata\lightsout an support at homeserversoftware punkt com und fügt einen Verweis auf diesen Beitrag ein.

Allen ein gutes, neues Jahr
Martin

Hallo Martin,

ich habe die Logs gemailt.

Ergänzender Hinweis:
Nach dem Jahreswechsel läuft wieder alles normal, wobei ich am 01.01. ein vom WHS initiertes Backup ("Automatisches Backup") ohne aktivien LO-Dienst habe durchlaufen lassen.