LO Service wird sporadisch neu gestartet

[Nobby1805]

Gestern ist mir "zufällig" aufgefallen, dass laut den "aufgezeichneten Ereignissen" im LO-Tab der Konsole regelmäßig eine Neustart des Servers gemeldet wird

Neustart.PNG (6.75 KiB) 4465 mal betrachtet

Das ist aber nicht richtig! Mein Server läuft z.Zt. rund um die Uhr weil dort im Minutentakt eine "Überwachung" durchgeführt wird.

Im Eventlog finde ich nur einen Eintrag, dass der Service neu gestartet worden ist

Neustart EvLog.PNG (6.54 KiB) 4465 mal betrachtet

aber keinen Hinweis, das und warum er beendet worden ist

Auch im Logfile des Service finde ich keinen Hinweis auf den Absturz

Code: Alles auswählen

2014-09-01 02:55:38:445 [   7] DEBUG network counter change: Check every 00:05:00 triggered
2014-09-01 02:55:38:461 [   7] DEBUG .
2014-09-01 02:55:48:445 [   7] DEBUG .
2014-09-01 02:55:58:445 [   7] DEBUG .
2014-09-01 02:56:08:445 [   7] DEBUG .
2014-09-01 02:56:18:430 [   7] DEBUG .
2014-09-01 02:56:28:414 [   7] DEBUG .
2014-09-01 02:56:38:430 [   7] DEBUG .
2014-09-01 02:56:52:070 [   1] INFO  

2014-09-01 02:56:52:148 [   1] INFO  >LoService ctor
2014-09-01 02:56:52:148 [   1] INFO  <LoService ctor
2014-09-01 02:56:52:226 [   4] DEBUG   RequestAdditionalTime
2014-09-01 02:56:52:226 [   4] DEBUG ============================
2014-09-01 02:56:52:226 [   4] DEBUG > OnStart
2014-09-01 02:56:54:992 [   4] DEBUG ============================
2014-09-01 02:56:54:992 [   4] DEBUG > LightsOutCore Ctor
2014-09-01 02:56:55:008 [   4] DEBUG LightsOutService Version : 1.5.5.2136
2014-09-01 02:56:55:008 [   4] DEBUG .NET Framework Version   : 2.0.50727.3655
2014-09-01 02:56:55:023 [   4] DEBUG Running on machine/OS    : HOMESERVER Windows Server 2003 [Windows Home Server Service Pack 2], 5.2.3790.131072, CPU x86, OS x86, Program x86
2014-09-01 02:56:55:023 [   4] DEBUG < LightsOutCore Ctor
2014-09-01 02:56:55:023 [   4] DEBUG ============================
2014-09-01 02:56:55:133 [   4] DEBUG > LOO: LightsOutOptions Ctor
2014-09-01 02:56:55:211 [   4] DEBUG LOO: Changed WaitTime=20
2014-09-01 02:56:55:226 [   4] DEBUG LOO: Changed StartStopServices=Spooler,WHSHealth
2014-09-01 02:56:55:226 [   4] DEBUG LOO: Changed MonitorCpuLoadValue=10

nur im LO-logfile sieht es zur Zeit des Absturzes etwas andesr aus als davor und danach

2014-09-01 02:49:08:555 [ 121] DEBUG Invoke ReadDeviceListFromFile
2014-09-01 02:49:08:555 [ 1] DEBUG ReadDeviceListFromFile
2014-09-01 02:50:28:586 [ 121] DEBUG > AddressInfoList.ReadList
2014-09-01 02:50:28:586 [ 121] DEBUG < AddressInfoList.ReadList has 15 elements in new list
2014-09-01 02:50:28:586 [ 121] DEBUG --- GlobalDeviceList is now updated, 15 entries
2014-09-01 02:50:28:601 [ 121] DEBUG Invoke ReadDeviceListFromFile
2014-09-01 02:50:28:601 [ 1] DEBUG ReadDeviceListFromFile
2014-09-01 02:56:39:351 [ 21] DEBUG PipeClient: Read 0 bytes, already disposed=False
2014-09-01 02:56:39:414 [ 21] DEBUG ConsolePipeClient: Server has disconnected
2014-09-01 02:56:59:242 [ 1] DEBUG PipeClient: Connected to server, receive thread started, handle 11028
2014-09-01 02:56:59:242 [ 1] DEBUG ConsolePipeClient connected = True
2014-09-01 02:56:59:273 [ 72] DEBUG PipeClient: receive thread entering read loop
2014-09-01 02:56:59:351 [ 72] DEBUG Invoke PipeMessageReceived
2014-09-01 02:56:59:351 [ 1] DEBUG PipeMessageReceived UpdateLicense 0
2014-09-01 02:56:59:351 [ 1] DEBUG License state now LicenseValid, error 0

[Martin]

Das sieht so aus, als ob der Dienst still und leise stirbt ohne eine Fehlerbehandlung aufzurufen. Schau mal ob der Eventlog evtl. mehr dazu verzeichnet hat.
Der SCM startet den Dienst bei einem Ausfall dann neu.

Eventuell ist da in den WHS Internas was faul. Einfach mal den Server neu starten und schauen ob es dann besser ist.

Gruß
Martin

[Nobby1805]

In den Eventlogs steht nichts weiter, ich habe jetzt mal den WHS neu gestartet ...

ich habe so ein Gefühl, als ob es hiermit zusammenhängt

2014-09-01 02:56:39:351 [ 21] DEBUG PipeClient: Read 0 bytes, already disposed=False
2014-09-01 02:56:39:414 [ 21] DEBUG ConsolePipeClient: Server has disconnected

was wird denn da genau gelesen ?

[Nobby1805]

Der Neustart des Servers hat nichts gebracht

Neustart 2.PNG (7.06 KiB) 4404 mal betrachtet

Noch eine Idee was ich machen kann bzw. wo kann mehr Logging durchgeführt werden ?

[Martin]

Der Ausschnitt aus dem Log dokumentiert nur, dass die Verbindung zwischen Konsole und Dienst (über eine Pipe) abgebrochen ist (da ja der Dienst nicht mehr läuft).
Ist denn im Ereignisprotokoll der Neustart des Dienstes zu sehen? Was wird da kurz vorher geloggt?

Meine beiden WHS v1 zeigen das Verhalten nicht. Gibt es eventuell in den WHS Logs unter %qlogs% noch etwas?

Gruß
Martin

[Nobby1805]

Hallo Martin,

Im EVT Anwendung steht folgendes ... in den anderen zu diesem Zeitraum gar nichts

Neustart EvLog 2.PNG (19.38 KiB) 4389 mal betrachtet

Im PartnerManager steht

********** Starting log, build Oct 7 2009 12:25:42 (6.0.2423.0), Process Id 14fc **********

[03.09.2014 03:47:32 944] CTransportConfig::ServerID Server ID is 716ef33b-d586-4ec3-b53b-1b250a5c1c73

das ist vermutlich der neue Start des Service

und im Transport-Log

[2014/09/03 03:31:00 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:31:06 d28] CTransportSinkManager::RealRoute Service sink for 274df3ef-462f78e0-e8b737ba-573be46380010108-b6f818e3007c822fc600031f returned an error 00000006, unregistering the sink.
[2014/09/03 03:33:38 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:34:28 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:34:56 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:35:38 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:36:58 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:37:28 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:39:48 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:40:18 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:40:38 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:47:25 d28] CTransportSinkManager::RealRoute Service sink for 92fee587-4ee6cee2-29ca9484-e99cb75f800706bf-b6f818e3007c822fc600032f returned an error 00000019, unregistering the sink.
[2014/09/03 03:47:25 d28] CTransportSinkManager::RealRoute Service sink for 28e791cd-4d34dcbd-e79144a0-e1a94dc800706ba-b6f818e3007c822fc600032f returned an error 00000019, unregistering the sink.
[2014/09/03 03:47:25 d28] CTransportSinkManager::RealRoute Service sink for 15b1cae5-479bf55f-36606793-634c0157800706ba-b6f818e3007c822fc600032f returned an error 00000019, unregistering the sink.
[2014/09/03 03:47:34 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:47:34 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:47:34 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:47:34 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:47:34 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:47:34 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[2014/09/03 03:47:34 d28] CTransportSinkManager::ProcessRecvQueue Routing failure.
[03.09.2014 03:47:44 d28] ERROR: Sink *** Unknown sink *** (pid=0, GUID=c48622a4-c464-4050-9de0-aa3f60dc3cef) took 2062 ms to execute incoming message.

aber ähnliches findet sich immer wieder im Log

ich schau mal, ob ich mit dem ProcMon etwas einfangen kann

[Nobby1805]

Hallo Martin,

nachdem ich den ProcMon eingeschaltet hatte ist es jetzt längere Zeit nicht passiert .. aber letzte Nacht dann doch

Neustart 3.PNG (6.94 KiB) 4348 mal betrachtet

der ProcMon-Output endet mit einem Fehlercode ... vielleicht hilft dir das weiter

Code: Alles auswählen

01:55:01,4938461	LightsOutService.exe	5372	Process Exit		SUCCESS	Exit Status: -1073741819, User Time: 6469.6562500 seconds, Kernel Time: 1663.4062500 seconds, Private Bytes: 205.844.480, Peak Private Bytes: 219.111.424, Working Set: 199.462.912, Peak Working Set: 202.625.024

und dann hier noch die Umgebung der Stelle von der ich vermutet das hier das Problem ausgelöst wird

Code: Alles auswählen

01:54:48,8692758	LightsOutService.exe	5372	Thread Create		SUCCESS	Thread ID: 996
01:54:48,8703512	LightsOutService.exe	5372	Thread Create		SUCCESS	Thread ID: 3392
01:54:48,8705583	LightsOutService.exe	5372	Thread Create		SUCCESS	Thread ID: 4360
01:54:48,9080559	LightsOutService.exe	5372	Thread Create		SUCCESS	Thread ID: 5052
01:54:49,1193550	LightsOutService.exe	5372	Thread Exit		SUCCESS	Thread ID: 996, User Time: 0.0000000, Kernel Time: 0.0000000
01:54:49,1200008	LightsOutService.exe	5372	Thread Exit		SUCCESS	Thread ID: 3392, User Time: 0.0000000, Kernel Time: 0.0000000
01:54:49,1234586	LightsOutService.exe	5372	Thread Exit		SUCCESS	Thread ID: 5052, User Time: 0.0000000, Kernel Time: 0.0000000
01:54:49,1238131	LightsOutService.exe	5372	Thread Exit		SUCCESS	Thread ID: 4360, User Time: 0.0156250, Kernel Time: 0.0000000
01:54:49,1512864	LightsOutService.exe	5372	FASTIO_NETWORK_QUERY_OPEN	C:\Dokumente und Einstellungen\All Users\Anwendungsdaten\LightsOut\TaskList.xml	NAME NOT FOUND	
01:54:49,2107437	LightsOutService.exe	5372	IRP_MJ_CREATE	C:\Dokumente und Einstellungen\All Users\Anwendungsdaten\LightsOut\LightsOut.Service.2014-09-09.log	SUCCESS	Desired Access: Generic Write, Read Attributes, Disposition: OpenIf, Options: Synchronous IO Non-Alert, Non-Directory File, Open No Recall, Attributes: n/a, ShareMode: Read, Delete, AllocationSize: 0, OpenResult: Opened
01:54:49,2108686	LightsOutService.exe	5372	FASTIO_QUERY_INFORMATION	C:\Dokumente und Einstellungen\All Users\Anwendungsdaten\LightsOut\LightsOut.Service.2014-09-09.log	SUCCESS	Type: QueryStandardInformationFile, AllocationSize: 69.632, EndOfFile: 66.238, NumberOfLinks: 1, DeletePending: False, Directory: False
01:54:49,2109459	LightsOutService.exe	5372	IRP_MJ_WRITE	C:\Dokumente und Einstellungen\All Users\Anwendungsdaten\LightsOut\LightsOut.Service.2014-09-09.log	SUCCESS	Offset: 66.238, Length: 40
01:54:49,2111922	LightsOutService.exe	5372	IRP_MJ_CLEANUP	C:\Dokumente und Einstellungen\All Users\Anwendungsdaten\LightsOut\LightsOut.Service.2014-09-09.log	SUCCESS	
01:54:49,2115290	LightsOutService.exe	5372	IRP_MJ_DIRECTORY_CONTROL	C:\Dokumente und Einstellungen\All Users\Anwendungsdaten\LightsOut	CANCELLED	Type: NotifyChangeDirectory, Filter: FILE_NOTIFY_CHANGE_LAST_WRITE
01:54:49,2115412	LightsOutService.exe	5372	IRP_MJ_READ	C:	SUCCESS	Offset: 38.277.120, Length: 128, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O
01:54:55,5535356	LightsOutService.exe	5372	Thread Create		SUCCESS	Thread ID: 6048
01:54:58,8687211	LightsOutService.exe	5372	Thread Create		SUCCESS	Thread ID: 5952
01:54:58,8699464	LightsOutService.exe	5372	Thread Create		SUCCESS	Thread ID: 4588
01:54:58,8701563	LightsOutService.exe	5372	Thread Create		SUCCESS	Thread ID: 3732
01:54:58,8714639	LightsOutService.exe	5372	Thread Create		SUCCESS	Thread ID: 7396
01:54:59,0785908	LightsOutService.exe	5372	Thread Exit		SUCCESS	Thread ID: 5952, User Time: 0.0000000, Kernel Time: 0.0000000
01:54:59,0798180	LightsOutService.exe	5372	Thread Exit		SUCCESS	Thread ID: 7396, User Time: 0.0000000, Kernel Time: 0.0000000
01:54:59,0823878	LightsOutService.exe	5372	Thread Exit		SUCCESS	Thread ID: 3732, User Time: 0.0156250, Kernel Time: 0.0000000
01:54:59,0826981	LightsOutService.exe	5372	IRP_MJ_READ	C:\WINDOWS\Microsoft.NET\Framework\v1.1.4322\msvcr71.dll	SUCCESS	Offset: 122.880, Length: 32.768, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O
01:54:59,0965353	LightsOutService.exe	5372	IRP_MJ_READ	C:\WINDOWS\system32\netman.dll	SUCCESS	Offset: 181.248, Length: 32.768, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O
01:54:59,0965969	LightsOutService.exe	5372	IRP_MJ_READ	C:\$Mft	SUCCESS	Offset: 1.896.448, Length: 4.096, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O
01:54:59,1087162	LightsOutService.exe	5372	IRP_MJ_READ	C:\WINDOWS\system32\netshell.dll	SUCCESS	Offset: 291.840, Length: 32.768, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O
01:54:59,1087799	LightsOutService.exe	5372	IRP_MJ_READ	C:\$Mft	SUCCESS	Offset: 2.924.544, Length: 4.096, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O
01:54:59,1166552	LightsOutService.exe	5372	IRP_MJ_READ	C:\WINDOWS\Microsoft.NET\Framework\v2.0.50727\mscorwks.dll	SUCCESS	Offset: 5.614.592, Length: 512, I/O Flags: Non-cached, Paging I/O, Synchronous Paging I/O

Der Block vom 1. "thread create" bis zum "IRP_MJ_DIRECTORY_CONTROL" kommt regelmäßig alle 10 Sekunden ... endet aber sonst mit einem SUCCESS und hier mit "CANCELED"

[Martin]

Hm, fürs Logging setzte ich nlog ein. Eventuell ist das CANCELLED die Folge des stillen Crashs. Ich habe eher die MS WHS DLLs im Verdacht. Da hatte ich zu Anfang auch das Problem, dass die still und leise gestorben sind und sich kein Fehler abfangen lies. Ich hab dann manche Funktionen nicht mehr verwendet, da sich der Fehler anders nicht vermeiden lies. Da das so bisher nur bei dir auftritt und sonst keine Hinweise zu finden sind ist das etwas schwierig zu debuggen.

Gruß
Martin