Azure WebJob-Protokollierung stürzt ab, was können wir tun?

Question

Wir verwenden Azure, um mehrere WebJobs auszuführen. Einer unserer WebJob Funktionen hat die folgende Signatur:

public static Task ProcessFileUploadedMessageAsync(
    [QueueTrigger("uploads")] FileUploadedMessage message, 
    TextWriter logger, 
    CancellationToken cancellationToken) 

Diese Funktion ist die Überwachung einer Warteschlange für eine Nachricht, die eine Datei hochgeladen wurde anzeigt, die dann einen Import der Daten der Datei auslöst. Beachten Sie die Verwendung eines TextWriter als zweites Argument: Dies wird von der WebJobs-API-Infrastruktur bereitgestellt.

Unser Importvorgang ist ziemlich langsam (kann in einigen Fällen mehrere Stunden für einen einzelnen Dateiimport sein), daher schreiben wir regelmäßig Nachrichten in das Protokoll (über die TextWriter), um unseren Fortschritt zu verfolgen. Leider führen unsere größeren Dateien dazu, dass der WebJob-Hostingprozess aufgrund einer Protokollierungsausnahme beendet wird. Hier ist ein Beispiel-Stack-Trace aus dem Hosting-Prozess-Log:

[04/02/2016 03:44:59 > 660083: ERR ] 
[04/02/2016 03:45:00 > 660083: ERR ] Unhandled Exception: System.ArgumentOutOfRangeException: Index was out of range. Must be non-negative and less than the size of the collection. 
[04/02/2016 03:45:00 > 660083: ERR ] Parameter name: chunkLength 
[04/02/2016 03:45:00 > 660083: ERR ] at System.Text.StringBuilder.ToString() 
[04/02/2016 03:45:00 > 660083: ERR ] at System.IO.StringWriter.ToString() 
[04/02/2016 03:45:00 > 660083: ERR ] at Microsoft.Azure.WebJobs.Host.Loggers.UpdateOutputLogCommand.<UpdateOutputBlob>d__10.MoveNext() 
[04/02/2016 03:45:00 > 660083: ERR ] --- End of stack trace from previous location where exception was thrown --- 
[04/02/2016 03:45:00 > 660083: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) 
[04/02/2016 03:45:00 > 660083: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) 
[04/02/2016 03:45:00 > 660083: ERR ] at Microsoft.Azure.WebJobs.Host.Loggers.UpdateOutputLogCommand.<TryExecuteAsync>d__3.MoveNext() 
[04/02/2016 03:45:00 > 660083: ERR ] --- End of stack trace from previous location where exception was thrown --- 
[04/02/2016 03:45:00 > 660083: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) 
[04/02/2016 03:45:00 > 660083: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) 
[04/02/2016 03:45:00 > 660083: ERR ] at Microsoft.Azure.WebJobs.Host.Timers.RecurrentTaskSeriesCommand.<ExecuteAsync>d__0.MoveNext() 
[04/02/2016 03:45:00 > 660083: ERR ] --- End of stack trace from previous location where exception was thrown --- 
[04/02/2016 03:45:00 > 660083: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.ThrowForNonSuccess(Task task) 
[04/02/2016 03:45:00 > 660083: ERR ] at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task) 
[04/02/2016 03:45:00 > 660083: ERR ] at Microsoft.Azure.WebJobs.Host.Timers.TaskSeriesTimer.<RunAsync>d__d.MoveNext() 
[04/02/2016 03:45:00 > 660083: ERR ] --- End of stack trace from previous location where exception was thrown --- 
[04/02/2016 03:45:00 > 660083: ERR ] at Microsoft.Azure.WebJobs.Host.Timers.BackgroundExceptionDispatcher.<>c__DisplayClass1.<Throw>b__0() 
[04/02/2016 03:45:00 > 660083: ERR ] at System.Threading.ThreadHelper.ThreadStart_Context(Object state) 
[04/02/2016 03:45:00 > 660083: ERR ] at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) 
[04/02/2016 03:45:00 > 660083: ERR ] at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx) 
[04/02/2016 03:45:00 > 660083: ERR ] at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state) 
[04/02/2016 03:45:00 > 660083: ERR ] at System.Threading.ThreadHelper.ThreadStart() 
[04/02/2016 03:45:00 > 660083: SYS ERR ] Job failed due to exit code -532462766 
[04/02/2016 03:45:01 > 660083: SYS INFO] Process went down, waiting for 0 seconds 
[04/02/2016 03:45:01 > 660083: SYS INFO] Status changed to PendingRestart 

Das Hauptproblem ist, dass diese Ausnahme nicht von unserem Code ausgelöst wird, sondern durch etwas in der WebJobs API:

at Microsoft.Azure.WebJobs.Host.Loggers.UpdateOutputLogCommand.<UpdateOutputBlob>d__10.MoveNext() 

Wir haben versucht, Putting try...catch Blöcke um unsere Anrufe an die TextWriter, aber diese hatten keine Wirkung. Es scheint, dass Protokollnachrichten irgendwo zwischengespeichert und regelmäßig von einem separaten Thread in den Azure-Blobspeicher übertragen werden. Wenn dies der Fall ist, folgt daraus, dass wir die Ausnahme nicht einfangen können.

Hat jemand anderes das gleiche Problem oder kann jemand an eine mögliche Lösung oder Workaround denken?

---

Für Vollständigkeit, hier ist, wie wir die TextWriter für die Protokollierung verwenden:

await logger.WriteLineAsync("some text to log"); 

Nichts komplizierter als das.

---

UPDATE: Scheint, als ob dies als issue #675 on the WebJobs SDK GitHub berichtet wurde.

Answer 1

Sie async zur Methode hinzufügen sollte, wie folgt aus:

public async static Task ProcessFileUploadedMessageAsync(...) 

Details zu erhalten, können Sie this article