IOException: Log cannot be accessed because it is used by another process

[muhaook]

Bug Report

Symptom

run console application on .Net framework 4.6.2 with test cases in it. hit exception below:

Log: Exception creating FileSink System.IO.IOException: The process cannot access the file 'C:\ProgramData\OpenTelemetry .NET AutoInstrumentation\logs\otel-dotnet-auto-loader-cststdrv.exe-20088.log' because it is being used by another process.
   at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
   at System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShare share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share)
   at OpenTelemetry.AutoInstrumentation.Loader.FileSink..ctor(String path, Encoding encoding) in C:\muwork\shared\mikebitbucket\otel-dotnet-auto\src\OpenTelemetry.AutoInstrumentation.Loader\FileSink.cs:line 42
   at OpenTelemetry.AutoInstrumentation.Loader.StartupLogger.Log(String message, Object[] args) in C:\muwork\shared\mikebitbucket\otel-dotnet-auto\src\OpenTelemetry.AutoInstrumentation.Loader\StartupLogger.cs:line 39
Log: Exception creating FileSink System.IO.IOException: The process cannot access the file 'C:\ProgramData\OpenTelemetry .NET AutoInstrumentation\logs\otel-dotnet-auto-loader-cststdrv.exe-20088.log' because it is being used by another process.
   at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
   at System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShare share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share)
   at OpenTelemetry.AutoInstrumentation.Loader.FileSink..ctor(String path, Encoding encoding) in C:\muwork\shared\mikebitbucket\otel-dotnet-auto\src\OpenTelemetry.AutoInstrumentation.Loader\FileSink.cs:line 42
   at OpenTelemetry.AutoInstrumentation.Loader.StartupLogger.Log(String message, Object[] args) in C:\muwork\shared\mikebitbucket\otel-dotnet-auto\src\OpenTelemetry.AutoInstrumentation.Loader\StartupLogger.cs:line 39
Log: Exception creating FileSink System.IO.IOException: The process cannot access the file 'C:\ProgramData\OpenTelemetry .NET AutoInstrumentation\logs\otel-dotnet-auto-loader-cststdrv.exe-20088.log' because it is being used by another process.
   at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
   at System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShare share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share)
   at OpenTelemetry.AutoInstrumentation.Loader.FileSink..ctor(String path, Encoding encoding) in C:\muwork\shared\mikebitbucket\otel-dotnet-auto\src\OpenTelemetry.AutoInstrumentation.Loader\FileSink.cs:line 42
   at OpenTelemetry.AutoInstrumentation.Loader.StartupLogger.Log(String message, Object[] args) in C:\muwork\shared\mikebitbucket\otel-dotnet-auto\src\OpenTelemetry.AutoInstrumentation.Loader\StartupLogger.cs:line 39
Loading c:\tracer-home\net462\OpenTelemetry.AutoInstrumentation.dll
Loading c:\tracer-home\net462\OpenTelemetry.AutoInstrumentation.dll
Loading c:\tracer-home\net462\OpenTelemetry.AutoInstrumentation.dll

Runtime environment:

• OpenTelemetry Automatic Instrumentation version: 0.4.0
• OS: Windows server 2022
• .NET version: .NET Framework 4.6.2

[pjanotti]

🤔 at first I thought that the multiple loads were from different app domains, however, the code already includes the app domain as part of the log file name (even on v0.4.0). @muhaook if you can share some code with the repro it will be great. Meanwhile, I will try to repro on my own.

[pjanotti]

It is possible to repro the issue if multiple app-domains are created with the same friendly name. The fix should be simple: add the app-domain id.

[muhaook]

@pjanotti, yes, I agree. it is likely because of the same appdomain friendly name. This issue came from an internal customer. I'll try to reproduce it myself.

[pjanotti]

Thanks @muhaook, I was able to create a repro for the issue. I will submit PR to fix it this week.

[muhaook]

Hi @pjanotti , it turned out to be a multi-threading issue.
I can use a console application with 2 threads to reproduce this issue. Each thread in the sample is going to generate its own spans. in order to reproduce the issue, we need set OTEL_DOTNET_AUTO_DEBUG=true
The otel logs:

C:\ProgramData\OpenTelemetry .NET AutoInstrumentation\logs>dir
09/01/2023  16:02            14,352 otel-dotnet-auto-ConsoleAppNet462.exe-30828.log
09/01/2023  16:02               981 otel-dotnet-auto-loader-ConsoleAppNet462.exe-30828.log
09/01/2023  16:02           100,151 otel-dotnet-auto-native-ConsoleAppNet462-30828.log

The error on sample stdout/stderr:

Log: Exception creating FileSink System.IO.IOException: The process cannot access the file 'C:\ProgramData\OpenTelemetry .NET AutoInstrumentation\logs\otel-dotnet-auto-loader-ConsoleAppNet462.exe-30828.log' because it is being used by another process.
   at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)
   at System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShare share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share)
   at OpenTelemetry.AutoInstrumentation.Loader.FileSink..ctor(String path, Encoding encoding)
   at OpenTelemetry.AutoInstrumentation.Loader.StartupLogger.Log(String message, Object[] args)
Requester [<null>] requested [OpenTelemetry.AutoInstrumentation, Version=0.5.1.0, Culture=neutral, PublicKeyToken=c0db600a13f60b51]

I then made change to auto-instrumentation source code, added thread id to log file name:

afterwards, no error on sample stdout/stderr and otel logs look like below. there were 2 loader log files:

C:\ProgramData\OpenTelemetry .NET AutoInstrumentation\logs>dir
09/01/2023  16:05            14,352 otel-dotnet-auto-ConsoleAppNet462.exe-13776-1.log
09/01/2023  16:05               854 otel-dotnet-auto-loader-ConsoleAppNet462.exe-13776-1.log
09/01/2023  16:05               291 otel-dotnet-auto-loader-ConsoleAppNet462.exe-13776-7.log
09/01/2023  16:05           100,258 otel-dotnet-auto-native-ConsoleAppNet462-13776.log

Attahced please find otel logs before the fix and after the fix:
logs.zip

[pjanotti]

Thanks @muhaook! I will get to it later today.

[pjanotti]

Thanks for that @muhaook - there are then actually 2 issues:

1. The app domain friendly name clash;
2. A race to hold the file sink that is not properly protected - the multithread case that you described;