Seit Windows 10 werden die Logfiles vom Windows Update Service nicht mehr in einfach lesbare Log-Dateien sondern in sogenannte Event Trace Logfiles (ETL) geschrieben. Wieder einmal eine ganz tolle Idee von Microsoft, die besonders dann hilfreich ist wenn es ans Troubleshooten von Windows Update Problemen geht (die soll es ja angeblich hin und wieder geben).

Die ETL Files haben 2 eklatante Nachteile:

• man kann nicht mehr live (mittels tail oder anderen Tools) mitlesen
• lokal gibt es das Powershell Cmdlet "Get-WindowsUpdateLog", welches die ETLs in ein lesbares Log dekodieren und auf den Desktop legen. Leider ist man nicht immer lokal unterwegs, schon gar nicht wenn man im Enterprise Umfeld tätig ist.

Manuelles dekodieren ist möglich, aber natürlich nicht so einfach wie man es gerne hätte. Dazu muss man wie folgt vorgehen:

• Debug Symblols herunter laden und installieren: https://msdn.microsoft.com/en-us/windows/hardware/gg463028.aspx
• Tracefmt.exe (https://docs.microsoft.com/en-gb/windows-hardware/drivers/devtest/tracefmt) herunter laden (enthalten im jeweils aktuellen WDK: https://docs.microsoft.com/en-us/windows-hardware/drivers/download-the-wdk - Vorsicht: Enterprise hat eine eigene Version. Die tracefmt.exe findet man unter <CD Laufwerk>:\Program Files\Windows Kits\10\bin\10.0.16299.0\x64\tracefmt.exe).

Die Windows Update ETL Files befinden sich auf C:\Windows\logs\WindowsUpdate:

Mittels tracefmt.exe können diese ETLs nun in eine lesbares Logfile dekodiert werden:

tracefmt.exe -o windowsupate.log WindowsUpdate.20180308.103756.226.8.etl -r c:\Symbols

Möchte man mehrere ETLs auf einmal dekodieren, einfach durch Leerzeichen getrennt die entsprechenden Dateinamen angeben.

Das Ergebnis ist ein (halbwegs vernünftig) lesbares Logfile, wie man es von früheren Windows Versionen gewöhnt ist:

[0]0DA8.25DC::03/07/2018-14:37:26.883 [WUTraceLogging]{"name":"Misc","Info":"Got WSUS Client/Server URL: \"http://wsus.meine.firma.at/ClientWebService/client.asmx\""}
[0]0DA8.25DC::03/07/2018-14:37:26.900 [WUTraceLogging]{"name":"ProtocolTalker","Info":"OK to reuse existing configuration"}
[0]0DA8.25DC::03/07/2018-14:37:26.900 [WUTraceLogging]{"name":"ProtocolTalker","Info":"Existing cookie is valid, just use it"}
[0]0DA8.25DC::03/07/2018-14:37:26.900 [WUTraceLogging]{"name":"ProtocolTalker","Info":"PTInfo: Server requested registration"}
[0]0DA8.25DC::03/07/2018-14:37:26.916 [WUTraceLogging]{"name":"Misc","Info":"Got WSUS Reporting URL: \"http://wsus.meine.firma.at/ReportingWebService/ReportingWebService.asmx\""}
[0]0DA8.25DC::03/07/2018-14:37:26.916 [WUTraceLogging]{"name":"IdleTimer","Info":"WU operation (CLegacyEventUploader::HandleEvents) started; operation # 102; does use network; is at background priority"}
[0]0DA8.25DC::03/07/2018-14:37:26.916 [WUTraceLogging]{"name":"WebServices","Info":"Auto proxy settings for this web service call."}
[0]0DA8.25DC::03/07/2018-14:37:27.241 [WUTraceLogging]{"name":"IdleTimer","Info":"WU operation (CLegacyEventUploader::HandleEvents, operation # 102) stopped; does use network; is at background priority"}
[0]0DA8.246C::03/07/2018-14:47:27.250 [WUTraceLogging]{"name":"Agent","Info":"Earliest future timer found: "}
[0]0DA8.246C::03/07/2018-14:47:27.250 [WUTraceLogging]{"name":"Agent","Info":"    Timer: 29A863E7-8609-4D1E-B7CD-5668F857F1DB, Expires 2018-03-08 09:14:12, not idle-only, not network-only"}
[0]0DA8.13E0::03/07/2018-14:47:28.253 [WUTraceLogging]{"name":"Misc","Info":"CSusClientGlobal::DoServicePreShutdown"}
[0]0DA8.13E0::03/07/2018-14:47:28.253 [WUTraceLogging]{"name":"IdleTimer","Info":"Idle timer disabled in preparation for service shutdown"}
[0]0DA8.13E0::03/07/2018-14:47:28.253 [WUTraceLogging]{"name":"Misc","Info":"WUTaskManager uninit"}
[0]0DA8.13E0::03/07/2018-14:47:28.253 [WUTraceLogging]{"name":"Agent","Info":"Earliest future timer found: "}
[0]0DA8.13E0::03/07/2018-14:47:28.253 [WUTraceLogging]{"name":"Agent","Info":"    Timer: 29A863E7-8609-4D1E-B7CD-5668F857F1DB, Expires 2018-03-08 09:14:12, not idle-only, not network-only"}
[0]0DA8.13E0::03/07/2018-14:47:28.259 [WUTraceLogging]{"name":"Misc","Info":"CreateSessionStateChangeTrigger, TYPE:2, Enable:No"}
[0]0DA8.13E0::03/07/2018-14:47:28.259 [WUTraceLogging]{"name":"Misc","Info":"CreateSessionStateChangeTrigger, TYPE:4, Enable:No"}
[0]0DA8.13E0::03/07/2018-14:47:28.266 [WUTraceLogging]{"name":"Misc","Info":"Agent uninit"}
[0]0DA8.13E0::03/07/2018-14:47:28.269 [WUTraceLogging]{"name":"Misc","Info":"Reporter uninit"}
[0]0DA8.13E0::03/07/2018-14:47:28.269 [WUTraceLogging]{"name":"Misc","Info":"network cost manager uninit"}
[0]0DA8.13E0::03/07/2018-14:47:28.269 [WUTraceLogging]{"name":"Misc","Info":"Eventer uninit"}
[0]0DA8.13E0::03/07/2018-14:47:28.269 [WUTraceLogging]{"name":"Misc","Info":"ServiceManager uninit"}
[0]0DA8.13E0::03/07/2018-14:47:28.270 [WUTraceLogging]{"name":"Misc","Info":"PersistentTimeoutScheduler uninit"}
[0]0DA8.13E0::03/07/2018-14:47:28.270 [WUTraceLogging]{"name":"Misc","Info":"datastore uninit"}
[0]0DA8.13E0::03/07/2018-14:47:28.297 [WUTraceLogging]{"name":"Misc","Info":"setting cache uninit"}
[0]0DA8.13E0::03/07/2018-14:47:28.297 [WUTraceLogging]{"name":"Misc","Info":"security checker uninit"}
[0]0DA8.13E0::03/07/2018-14:47:28.297 [WUTraceLogging]{"name":"Misc","Info":"Test Hook uninit"}
[0]0DA8.13E0::03/07/2018-14:47:28.297 [WUTraceLogging]{"name":"Misc","Info":"IdleTimer uninit"}
[0]0DA8.13E0::03/07/2018-14:47:28.299 [WUTraceLogging]{"name":"Shared","Info":"* END * Service exit Exit code = 0x240001"}