getsentry / sentry-dotnet

Sentry SDK for .NET
https://docs.sentry.io/platforms/dotnet
MIT License
598 stars 207 forks source link

Some attachments not send on MAUI #3101

Open pierre-galaup opened 9 months ago

pierre-galaup commented 9 months ago

Package

Sentry.Maui

.NET Flavor

.NET

.NET Version

8.0.0

OS

Android

SDK Version

Sentry.Maui 3.41.3

Self-Hosted Sentry Version

No response

Steps to Reproduce

Hello,

On my MAUI application, I send a "SentrySdk.CaptureMessage" where I configure in the scope a number of attachments which are ZIP files that contain logs (NLog) :

scope.AddAttachment(attachment, AttachmentType.Default, "application/zip");

However, on some phones and quite randomly, some of these files are not sent. The files are not used and they are all stored in the same directory, and the zip is created in the same way.

I managed, with the Sentry DEBUG set to TRUE, to get the error :

Warning: Failed to serialize envelope item
System.InvalidOperationException: Arg_InvalidOperationException
  at System.Threading.Tasks.Sources.ManualResetValueTaskSourceCore`1[[System.Int64, System.Private.CoreLib, Version=8.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]].GetStatus(Int16 )
  at Microsoft.Win32.SafeHandles.SafeFileHandle.ThreadPoolValueTaskSource.GetStatus(Int16 )
  at System.IO.Strategies.BufferedFileStreamStrategy.ReadAsync(Byte[] , Int32 , Int32 , CancellationToken )
  at System.IO.FileStream.ReadAsync(Byte[] , Int32 , Int32 , CancellationToken )
  at Sentry.Internal.PartialStream.ReadAsync(Byte[] buffer, Int32 offset, Int32 count, CancellationToken cancellationToken)
  at System.IO.Stream.<CopyToAsync>g__Core|27_0(Stream , Stream , Int32 , CancellationToken )
  at Sentry.Protocol.Envelopes.EnvelopeItem.BufferPayloadAsync(IDiagnosticLogger logger, CancellationToken cancellationToken)
  at Sentry.Protocol.Envelopes.EnvelopeItem.SerializeAsync(Stream stream, IDiagnosticLogger logger, CancellationToken cancellationToken)
  at Sentry.Protocol.Envelopes.Envelope.SerializeAsync(Stream stream, IDiagnosticLogger logger, ISystemClock clock, CancellationToken cancellationToken)

I've only managed to reproduce this problem on Android phones.

Can you help me? Thanks

Expected Result

All attachments send

Actual Result

Some attachments not send

bitsandfoxes commented 9 months ago

Hey, sorry to see you run into issues. Chasing up a bit of what might be going on here it looks to me like the SDK chokes on reading the stream here https://github.com/getsentry/sentry-dotnet/blob/7fd6f20262e62761032f2d92fbcac65f9f8c04a4/src/Sentry/Internal/PartialStream.cs#L63

Afaik the stream originates from here https://github.com/getsentry/sentry-dotnet/blob/7fd6f20262e62761032f2d92fbcac65f9f8c04a4/src/Sentry/Internal/Http/CachingTransport.cs#L294

How consistently do you encounter this? Could you provide a repro for us to take a deeper look?

pierre-galaup commented 9 months ago

Hello,

Thank you for your reply.

Unfortunately I don't have an easy repo to provide. I have the impression that it only happens on Android (at least we've never had a problem on iOS) and only in RELEASE. But, I rarely keep logs of several days in DEBUG...

I can give you some more code information, like my Sentry initialization and how I send my logs (which come from NLog).

As I said, it's random and some ZIPs are sent correctly, and others not, in the same envelope. I'm sure that the files exist on the phone because I also send a file listing the files in the directory and they're in that file.

My sentry options:

            .UseSentry(options =>
            {
                // The DSN is the only required setting.
                options.Dsn = Configuration.SentryDsn;

                options.Debug = false;

#if IOS
                options.iOS.EnableAppHangTracking = false;
#endif

#if ANDROID
                options.Android.AnrEnabled = false;
#endif

                options.TracesSampleRate = 1.0;

                options.IncludeTextInBreadcrumbs = true;
                options.IncludeTitleInBreadcrumbs = true;
                options.IncludeBackgroundingStateInBreadcrumbs = true;

                options.AutoSessionTracking = true;
                options.IsGlobalModeEnabled = true;

                options.CacheDirectoryPath = Environment.GetFolderPath(Environment.SpecialFolder.LocalApplicationData);

                options.Environment = Configuration.Environment;
                options.SendDefaultPii = false;
            })

The code used to send these files:

            var directory = new DirectoryInfo(Path.Combine(Environment.GetFolderPath(Environment.SpecialFolder.LocalApplicationData), "logs"));

            var getFiles = directory.GetFiles();
            var attachments = new List<string>();

            foreach (var logFile in getFiles)
            {
                var zipFile = logFile.FullName.Replace($"{logFile.Extension}", ".zip");
                attachments.Add(zipFile);
                using var zipArchive = new ZipOutputStream(File.Create(zipFile));
                zipArchive.SetLevel(9);

                var buffer = new byte[102400];

                var entry = new ZipEntry(logFile.Name)
                {
                    DateTime = DateTime.Now
                };

                zipArchive.PutNextEntry(entry);

                using var fs = new FileStream(logFileName, FileMode.Open, FileAccess.Read, FileShare.ReadWrite);
                int sourceBytes;
                do
                {
                    sourceBytes = fs.Read(buffer, 0, buffer.Length);
                    zipArchive.Write(buffer, 0, sourceBytes);
                } while (sourceBytes > 0);

                zipArchive.Finish();
                zipArchive.Close();
           }

        SentrySdk.CaptureMessage("ErrorReport", scope =>
        {
            scope.ClearAttachments();

            if (attachments != null)
            {
                foreach (var attachment in attachments)
                {
                    scope.AddAttachment(attachment, AttachmentType.Default, "application/zip");
                }
            }

            scope.SetTag("XXX", XXX);
            scope.SetTag("XXX", XXX);
            scope.SetTag("XXX", XXX);

            scope.SetTag("XXX", XXX);

            scope.SetFingerprint("XXXXX");
        }, SentryLevel.Debug);

My RELEASE CSPROJ:

    <PropertyGroup Condition="'$(Configuration)'=='Release'">
        <UseInterpreter>false</UseInterpreter>
        <MtouchDebug>False</MtouchDebug>
        <AndroidPackageFormat>aab</AndroidPackageFormat>
        <AndroidDexTool>d8</AndroidDexTool>
        <AndroidLinkTool/>
        <AndroidUseAapt2>true</AndroidUseAapt2>
        <AndroidEnableMultiDex>false</AndroidEnableMultiDex>
        <AndroidStoreUncompressedFileExtensions>.mp3</AndroidStoreUncompressedFileExtensions>
        <AndroidHttpClientHandlerType>Xamarin.Android.Net.AndroidClientHandler</AndroidHttpClientHandlerType>
        <AndroidEnableSGenConcurrent>true</AndroidEnableSGenConcurrent>
        <Optimize>true</Optimize>
        <BundleAssemblies>false</BundleAssemblies>
        <AndroidUseSharedRuntime>false</AndroidUseSharedRuntime>
        <EmbedAssembliesIntoApk>true</EmbedAssembliesIntoApk>
        <MtouchLink>SdkOnly</MtouchLink>
        <MtouchEnableSGenConc>true</MtouchEnableSGenConc>
        <DefineConstants/>
        <CreatePackage>false</CreatePackage>
        <MtouchUseLlvm>true</MtouchUseLlvm>
        <EnableCodeSigning>true</EnableCodeSigning>
        <MtouchArch>ARM64</MtouchArch>
        <RunAOTCompilation>true</RunAOTCompilation>
        <AndroidEnableProfiledAot>false</AndroidEnableProfiledAot>
        <EnableLLVM>true</EnableLLVM>
        <AndroidStripILAfterAOT>true</AndroidStripILAfterAOT>

        <CopyDebugSymbolFilesFromPackages>true</CopyDebugSymbolFilesFromPackages>
        <CopyDocumentationFilesFromPackages>true</CopyDocumentationFilesFromPackages>

        <!-- Sends symbols to Sentry, enabling symbolication of stack traces. -->
        <SentryUploadSymbols>true</SentryUploadSymbols>
        <!-- Sends sources to Sentry, enabling display of source context. -->
        <SentryUploadSources>false</SentryUploadSources>
        <!-- If you are targeting Android, sends proguard mapping file to Sentry. -->
        <SentryUploadAndroidProguardMapping>true</SentryUploadAndroidProguardMapping>
    </PropertyGroup>
bruno-garcia commented 9 months ago

Could it be there's some other part of the app that does file rotation? Deleting the old one while Sentry is trying to read from it?

It's odd, System.InvalidOperationException: Arg_InvalidOperationException doesn't give us much and the error is just coming from .NET trying to read from the stream.

Unrelated to this issue but worth noting Sentry gzip's the payload already so no need in gzip the logs yourself. You could attach them as-is.

pierre-galaup commented 9 months ago

Hello,

I tried to make a copy of each file before zipping it:

                if (logFile.Extension == ".csv") // Copy the log
                {
                    logFileToCopy = logFileName = logFileName.Replace(".csv", ".Copy.csv");

                    using var inputFile = new FileStream(logFile.FullName, FileMode.Open, FileAccess.Read, FileShare.ReadWrite);
                    using var outputFile = new FileStream(logFileName, FileMode.Create);
                    var buf = new byte[102400];
                    int bytes;
                    while ((bytes = inputFile.Read(buf, 0, buf.Length)) > 0)
                    {
                        outputFile.Write(buf, 0, bytes);
                    }
                }

But it still happens. I don't think it's the NLOG rotation... My NLog.config :

        <target xsi:type="File" name="logfile"
                fileName="${specialfolder:folder=LocalApplicationData}/logs/App.${shortdate}.csv"
                keepFileOpen="true"
                openFileCacheTimeout="30"
                maxArchiveFiles="7"
                maxArchiveDays="7"
                archiveEvery="Day"
                archiveAboveSize="8388608"
                archiveFileName="${specialfolder:folder=LocalApplicationData}/logs/App.Archive.{#####}.csv"
                archiveNumbering="Date"
                archiveDateFormat="yyyy-MM-dd"
                encoding="utf-8">

I've also tried sending SENTRY a byte[] directly:

            foreach (var attachment in attachments)
            {
                using var fs = new FileStream(attachment, FileMode.Open, FileAccess.Read, FileShare.ReadWrite);
                sentryAttachments.Add(Path.GetFileName(attachment), ReadFully(fs));
            }

            return sentryAttachments;

            static byte[] ReadFully(Stream input)
            {
                var buffer = new byte[102400];
                using var ms = new MemoryStream();
                int read;
                while ((read = input.Read(buffer, 0, buffer.Length)) > 0)
                {
                    ms.Write(buffer, 0, read);
                }
                return ms.ToArray();
            }

But that didn't work either.

I've run out of test ideas of my own. And without repro I know that on your side it's complicated.

I'll try to see if I can make a repro that reproduces it, just extracting the parts that make up the log and sending it to SENTRY.

bruno-garcia commented 9 months ago

With that last snippet it seems like you're passing the bytes straight to the attachment. So Sentry shouldn't be competing with the file with any other thread/lib/etc.

So if this happens even in this case, it's possible we have a bug somewhere. Is the stack trace still coming through BufferPayloadAsync ?

pierre-galaup commented 9 months ago

Hello,

It's the same error. The phone of one of my testers has the bug in RELEASE, so I can easily test with it if needed (unfortunately I can't DEBUG on it).

I also tried sending the CSV file directly, without zipping it, and it didn't send either.

I tested something:

The same logs are sent to SENTRY and by mail (with MAUI ESSENTIALS).

With SENTRY I don't receive all the logs. By e-mail I receive and can open all the log files.

So, in fact, I think the problem is with Sentry.

bruno-garcia commented 9 months ago

The same logs are sent to SENTRY and by mail (with MAUI ESSENTIALS).

So here there could be a race condition? Is it the same Stream object sent on both? If you disable the email feature, is Sentry able to send it through?

pierre-galaup commented 9 months ago

It was just a test I did once to see if the files were corrupted or not.

I don't send the files at the same time to avoid any problems. I send the e-mail first and when I receive it I load the same files sent by e-mail in byte[] and send them by Sentry. And that's when some of them are missing, whereas by e-mail I have them all. And I get the same error stacktrace.

bruno-garcia commented 9 months ago

It was just a test I did once to see if the files were corrupted or not.

I don't send the files at the same time to avoid any problems. I send the e-mail first and when I receive it I load the same files sent by e-mail in byte[] and send them by Sentry. And that's when some of them are missing, whereas by e-mail I have them all. And I get the same error stacktrace.

Do you know their size? Sentry has limits in place. But afaik attachment is like 10Mb

pierre-galaup commented 9 months ago

Hello,

The log file size maximum is 2/3 Mb and most of the time < 1Mb.

I think I've found the problem. It comes from the <EnableLLVM>true</EnableLLVM> compilation flag.

If I remove it, the logs are sent, including the old ones (the ones that weren't sent before).

I provide a quick sample that reproduces my problem in a "fast" version (log rotation 1 minute and it logs a lot). If you compile in DEBUG mode, no problem. If you compile in RELEASE with EnableLLVM set to TRUE, the logs almost never arrive (the compilation is very long, just so you know). If you compile in RELEASE with EnableLLVM set to FALSE, no problem.

But I don't know why... The EnableLLVM flag is essential for us because it improves overall application performance.

--

SentryDebugHelper.zip

For the SAMPLE project, there are 3 buttons, 1 to send by e-mail (you need to define the target address in the code), 1 to send to SENTRY giving the FILENAME (you need to define the DSN) and 1 to send to SENTRY with one byte[] per file (you need to define the DSN).

Wait several minutes before sending the logs (several files are created).

A files.zip file is also sent, containing all current logs (which should be on SENTRY).

You can see in the e-mail that all the files are there, but not in SENTRY. The EnableLLVM is in the csproj, I've put a TODO next to it.

jamescrosswell commented 9 months ago

Hi @pierre-galaup,

Thanks for sending through the sample. I can reproduce the problem on my own machine... however it's extremely challenging to debug.

When I run the app in Debug mode, after about 5 or 10 seconds I'm getting an error:

Failed to establish connection to debugger agent

Is that something you've bumped into before? The only reference I found googling for this is here, and that didn't help.

Also, are you using Windows or macOS for development?

pierre-galaup commented 9 months ago

Hello @jamescrosswell,

I use a WINDOWS and MAC environment. And always with Rider. I'm using a Pixel 4A as a target. To make this SAMPLE I used my WINDOWS.

Maybe by lowering the number of DEBUGs (await Task.Delay(10); => await Task.Delay(100); or more), it will be easier to DEBUG? But will it always reproduce the problem?

Indeed it's very complicated to DEBUG with this FLAG activated, I use a lot of logging with ADB to help me. But clearly debuging like this is very complex.

I don't have any other solution, I usually don't DEBUG with the EnableLLVM flag set to TRUE!

jamescrosswell commented 9 months ago

Hi @pierre-galaup , just following up on this.

I added Sentry.NLog to the sample you provided:

dotnet add package Sentry.NLog -v 4.1.1

Then I hooked this up with Diagnostic logging enabled (that causes Sentry to send it's diagnostic logs to the NLog logger... basically they end up in LogCat):

        LogManager.Setup().LoadConfigurationFromAssemblyResource(typeof(App).Assembly);
        LogManager.Configuration.AddSentry(o =>
        {
            o.MinimumBreadcrumbLevel = NLog.LogLevel.Debug;
            o.MinimumEventLevel = NLog.LogLevel.Error;            
        });

        var builder = MauiApp.CreateBuilder();
        builder
            .UseMauiApp<App>()
            .UseSentry(options =>
            {
                options.DiagnosticLevel = SentryLevel.Debug;

With that wired up, I get a bit more information in LogCat even if the debugger won't stay attached to the process that's running in Android:

2024-02-15 14:50:56.008  9130-9159  DOTNET                  com.companyname.sentrydebughelper    I    Debug: Android: Serializing object: {     "reportType": "SendLogs" }
2024-02-15 14:50:56.010  9130-9209  DOTNET                  com.companyname.sentrydebughelper    I  Warning: Failed to serialize envelope item
                                                                                                    System.InvalidOperationException: Arg_InvalidOperationException
2024-02-15 14:50:56.010  9130-9209  DOTNET                  com.companyname.sentrydebughelper    I     at System.Threading.Tasks.Sources.ManualResetValueTaskSourceCore`1[[System.Int64, System.Private.CoreLib, Version=8.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]].GetStatus(Int16 )
                                                                                                       at Microsoft.Win32.SafeHandles.SafeFileHandle.ThreadPoolValueTaskSource.GetStatus(Int16 )
                                                                                                       at System.IO.Strategies.BufferedFileStreamStrategy.ReadAsync(Byte[] , Int32 , Int32 , CancellationToken )
2024-02-15 14:50:56.010  9130-9209  DOTNET                  com.companyname.sentrydebughelper    I     at System.IO.FileStream.ReadAsync(Byte[] , Int32 , Int32 , CancellationToken )
                                                                                                       at Sentry.Internal.PartialStream.ReadAsync(Byte[] , Int32 , Int32 , CancellationToken )
2024-02-15 14:50:56.010  9130-9209  DOTNET                  com.companyname.sentrydebughelper    I     at System.IO.Stream.<CopyToAsync>g__Core|27_0(Stream , Stream , Int32 , CancellationToken )
                                                                                                       at Sentry.Protocol.Envelopes.EnvelopeItem.BufferPayloadAsync(IDiagnosticLogger , CancellationToken )
                                                                                                       at Sentry.Protocol.Envelopes.EnvelopeItem.SerializeAsync(Stream , IDiagnosticLogger , CancellationToken )
2024-02-15 14:50:56.010  9130-9209  DOTNET                  com.companyname.sentrydebughelper    I     at Sentry.Protocol.Envelopes.Envelope.SerializeAsync(Stream , IDiagnosticLogger , ISystemClock , CancellationToken )

TBH that's not helping a lot. The last thing that happens in the sentry code before the error occurs is here:

https://github.com/getsentry/sentry-dotnet/blob/e75d537c14ded617c99eb33f19cf4ce69ca4de36/src/Sentry/Internal/PartialStream.cs#L63-L64

Then the FileStream.ReadAsync method throws:

System.InvalidOperationException: Arg_InvalidOperationException
    at System.Threading.Tasks.Sources.ManualResetValueTaskSourceCore`1[[System.Int64, System.Private.CoreLib, Version=8.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]].GetStatus(Int16 )
    at Microsoft.Win32.SafeHandles.SafeFileHandle.ThreadPoolValueTaskSource.GetStatus(Int16 )
    at System.IO.Strategies.BufferedFileStreamStrategy.ReadAsync(Byte[] , Int32 , Int32 , CancellationToken )
    at System.IO.FileStream.ReadAsync(Byte[] , Int32 , Int32 , CancellationToken )

Following the rabbit hole there goes: FileStream > BufferedFileStreamStrategy > ThreadPoolValueTaskSource > ManualResetValueTaskSourceCore.

I have no idea what's causing that though.

bruno-garcia commented 9 months ago

I think it's worth opening a ticket on https://github.com/xamarin/xamarin-android about this

tranb3r commented 6 months ago

I'm having the same issue when using hint.AddAttachment (with LLVM enabled). I can confirm it's actually caused by FileStream.ReadAsync. Is there a workaround?

jamescrosswell commented 6 months ago

I can confirm it's actually caused by FileStream.ReadAsync.

I think for this to be actionable by the Xamarin team, we need a simpler reproduction of the issue. vargaz asked for that so if you can reproduce this without wiring up Sentry (just a vanilla Maui app with an event handler that calls Stream.CopyToAsync, for example - which is what the Sentry library is doing) I think vargaz would be able to help us.

tranb3r commented 6 months ago

I've just added a repro.

tranb3r commented 4 months ago

Any update? If the dotnet issue cannot be fixed now, maybe there is another FileStream method that could be used as a workaround?

bitsandfoxes commented 4 months ago

We'll have to look into that workaround.

jamescrosswell commented 4 months ago

We'll have to look into that workaround.

I can't see any obvious way to do that... it's pretty low level stuff. This leads to this, which even has special stuff baked into the Task Library to support it (that we can't access, even if we were crazy enough to try). I think the only practical solution here is to seek resolution with Microsoft.