Azure-webjobs-sdk: Concurrency issue in CompositeTraceWriter
Seeing the following stack trace in the wild:
System.InvalidOperationException : Collection was modified; enumeration operation may not execute.
at System.ThrowHelper.ThrowInvalidOperationException(ExceptionResource resource)
at System.Collections.Generic.List`1.Enumerator.MoveNextRare()
at System.Collections.Generic.List`1.Enumerator.MoveNext()
at Microsoft.Azure.WebJobs.Host.CompositeTraceWriter.InvokeTraceWriters(TraceEvent traceEvent)
at Microsoft.Azure.WebJobs.Host.CompositeTraceWriter.Trace(TraceEvent traceEvent)
at Microsoft.Azure.WebJobs.Host.Loggers.TraceWriterFunctionInstanceLogger.LogFunctionCompletedAsync(FunctionCompletedMessage message,CancellationToken cancellationToken)
at async Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor.TryExecuteAsync(IFunctionInstance functionInstance,CancellationToken cancellationToken)
at async Microsoft.Azure.WebJobs.Host.Executors.ShutdownFunctionExecutor.TryExecuteAsync(IFunctionInstance instance,CancellationToken cancellationToken)
at async Microsoft.Azure.WebJobs.JobHost.CallAsync(??)
at async Microsoft.Azure.WebJobs.Script.Script
This is coming from the code here.
mathewc
All 7 comments
Interesting. I don't see us modifying that collection anywhere so I'm not sure where this is happening. Warrants investigation.
brettsam
on 26 Jan 2018
We're running into a potentially similar issue. We only noticed this when our app service got into a funky state prior to crashing. Here's the stack trace:
"Exception": "Exception: Probable I/O race condition detected while copying memory. The I/O package is not thread safe by default. In multithreaded applications, a stream must be accessed in a thread-safe way, such as a thread-safe wrapper returned by TextReader's or TextWriter's Synchronized methods. This also applies to classes like StreamWriter and StreamReader.\n 聽 at System.Buffer.InternalBlockCopy(Array src, Int32 srcOffsetBytes, Array dst, Int32 dstOffsetBytes, Int32 byteCount)
聽 聽at System.IO.StreamWriter.Write(Char[] buffer, Int32 index, Int32 count)
聽 聽at System.IO.TextWriter.WriteLine(String value)
聽 聽at Microsoft.Azure.WebJobs.Host.CompositeTraceWriter.InvokeTextWriter(TraceEvent traceEvent)
聽 聽at Microsoft.Azure.WebJobs.Host.CompositeTraceWriter.Trace(TraceEvent traceEvent)
聽 聽at Microsoft.Azure.WebJobs.Host.CompositeTraceWriter.InvokeTraceWriters(TraceEvent traceEvent)
聽 聽at Microsoft.Azure.WebJobs.Host.CompositeTraceWriter.Trace(TraceEvent traceEvent)
聽 聽at Microsoft.Azure.WebJobs.Script.CompositeTraceWriter.Trace(TraceEvent traceEvent) in C:\projects\azure-webjobs-sdk-script\src\WebJobs.Script\Diagnostics\CompositeTraceWriter.cs:line 35
聽 聽at Microsoft.Azure.WebJobs.Script.InterceptingTraceWriter.Trace(TraceEvent traceEvent) in C:\projects\azure-webjobs-sdk-script\src\WebJobs.Script\Diagnostics\InterceptingTraceWriter.cs:line 31
聽 聽at Microsoft.Azure.WebJobs.Host.TraceWriter.Info(String message, String source)
mattmcdEcova
on 31 Jan 2018
@brettsam @mathewc There is no code in CompositeTraceWriter that mutates the collection but if you look carefully you'll see we pass a collection in and we don't make a copy of it:
Is that deliberate or by accident? If its by accident, then perhaps simply copying the collection here would be enough to prevent this.
paulbatum
on 7 Feb 2018
@brettsam Is this change included in Microsoft.Azure.WebJobs v.2.2.0?
BenyChernyak1
on 23 Oct 2018
Yes -- https://github.com/Azure/azure-webjobs-sdk/releases/tag/v2.2.0 shows it as included in that release.
Are you seeing the same error? If so -- can you share the stack trace with us here?
brettsam
on 25 Oct 2018
I can still see the error with v.2.2.0
Probable I/O race condition detected while copying memory. The I/O package is not thread safe by default. In multithreaded applications, a stream must be accessed in a thread-safe way, such as a thread-safe wrapper returned by TextReader's or TextWriter's Synchronized methods. This also applies to classes like StreamWriter and StreamReader.
See below the stacktrace, parsed by AppInsights ;-)
[{"parsedStack":[{"assembly":"mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089","method":"System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw","level":0,"line":0},{"assembly":"Microsoft.Azure.WebJobs.Host, Version=2.3.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35","method":"Microsoft.Azure.WebJobs.Host.Executors.FunctionExecutor+2.InvokeAsync","level":11,"line":0},{"assembly":"Microsoft.Azure.WebJobs.Host, Version=2.3.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35","method":"Microsoft.Azure.WebJobs.Host.Executors.FunctionInvoker2+
eeertel
on 6 Nov 2018
Thanks for the stack trace. I was able to write a test to see this. PR to fix it is: #2003
brettsam
on 6 Nov 2018
Related issues
mslugx
路
3Comments
drchilds
路
4Comments
lopezbertoni
路
4Comments
nibras85
路
3Comments
mathewc
路
5Comments
Most helpful comment
@brettsam @mathewc There is no code in CompositeTraceWriter that mutates the collection but if you look carefully you'll see we pass a collection in and we don't make a copy of it:
https://github.com/Azure/azure-webjobs-sdk/blob/7dd9681609613f79cb73cbc13d28c5161ca1d7c3/src/Microsoft.Azure.WebJobs.Host/CompositeTraceWriter.cs#L21-L25
Is that deliberate or by accident? If its by accident, then perhaps simply copying the collection here would be enough to prevent this.