microsoft / ApplicationInsights-Profiler-AspNetCore

Application Insights Profiler sample and documentation
MIT License
66 stars 22 forks source link

Could not get the stamp id. Aborting the upload process #202

Closed Eneuman closed 5 months ago

Eneuman commented 8 months ago

Describe the bug I'm running the profiler in a container in AKS. About 2 minutes fter ethe container has started i receive the following error in the logs:

 2023-11-02 19:15.11 -- info: Microsoft.Hosting.Lifetime[0]                                                          
       Hosting environment: Staging                                                                                  
 2023-11-02 19:15.11 -- info: Microsoft.Hosting.Lifetime[0]                                                          
       Content root path: /app                                                                                       
 2023-11-02 19:17.11 -- fail: Microsoft.ApplicationInsights.Profiler.Core.UploaderProxy.TraceUploaderProxy[0]        
       Could not get the stamp id. Aborting the upload process.                                                      
 2023-11-02 19:17.41 -- fail: Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider[0]                 
       Unexpected error happens on stopping service profiler.                                                        
       System.OperationCanceledException: The operation was canceled.                                               
          at System.Threading.CancellationToken.ThrowOperationCanceledException()                                    
          at System.Threading.CancellationToken.ThrowIfCancellationRequested()                                       
          at System.IO.Pipes.NamedPipeClientStream.ConnectInternal(Int32 timeout, CancellationToken cancellationToke 
 n, Int32 startTime)                                                                                                 
          at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionConte 
 xt executionContext, ContextCallback callback, Object state)                                                        
       --- End of stack trace from previous location ---                                                             
          at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionConte 
 xt executionContext, ContextCallback callback, Object state)                                                        
          at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)      
       --- End of stack trace from previous location ---                                                             
          at Microsoft.ApplicationInsights.Profiler.Core.IPC.DuplexNamedPipeService.ConnectAsync(String pipeName, Ca 
 ncellationToken cancellationToken)                                                                                  
          at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.<>c__DisplayClass4_0.<<PostStopProc 
 essAsync>b__0>d.MoveNext()                                                                                          
       --- End of stack trace from previous location ---                                                             
          at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.PostStopProcessAsync(PostStopOption 
 s e, CancellationToken cancellationToken)                                                                           
 2023-11-02 19:17.41 -- fail: Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider[0]                 
       Unexpected error happens on stopping service profiler tracing.                                                
       System.OperationCanceledException: The operation was canceled.                                                
          at System.Threading.CancellationToken.ThrowOperationCanceledException()                                   
          at System.Threading.CancellationToken.ThrowIfCancellationRequested()                                       
          at System.IO.Pipes.NamedPipeClientStream.ConnectInternal(Int32 timeout, CancellationToken cancellationToke 
 n, Int32 startTime)                                                                                                 
          at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionConte 
 xt executionContext, ContextCallback callback, Object state)                                                        
       --- End of stack trace from previous location ---                                                             
          at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionConte 
 xt executionContext, ContextCallback callback, Object state)                                                        
          at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)      
       --- End of stack trace from previous location ---                                                             
          at Microsoft.ApplicationInsights.Profiler.Core.IPC.DuplexNamedPipeService.ConnectAsync(String pipeName, Ca 
 ncellationToken cancellationToken)                                                                                  
          at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.<>c__DisplayClass4_0.<<PostStopProc 
 essAsync>b__0>d.MoveNext()                                                                                          
       --- End of stack trace from previous location ---                                                             
          at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.PostStopProcessAsync(PostStopOption 
 s e, CancellationToken cancellationToken)                                                                           
          at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.StopServiceProfilerAsync(IProfilerS 
 ource source, CancellationToken cancellationToken)                                                                  
 2023-11-02 19:17.41 -- fail: Microsoft.ApplicationInsights.Profiler.Core.Orchestration.OneTimeSchedulingPolicy[0]   
       Unexpected exception in the last cycle.
       System.OperationCanceledException: The operation was canceled.                                                
          at System.Threading.CancellationToken.ThrowOperationCanceledException()                                    
          at System.Threading.CancellationToken.ThrowIfCancellationRequested()                                       
          at System.IO.Pipes.NamedPipeClientStream.ConnectInternal(Int32 timeout, CancellationToken cancellationToke
 n, Int32 startTime)                                                                                                
          at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionConte
 xt executionContext, ContextCallback callback, Object state)                                                        
       --- End of stack trace from previous location ---                                                             
          at System.Threading.ExecutionContext.RunFromThreadPoolDispatchLoop(Thread threadPoolThread, ExecutionConte 
 xt executionContext, ContextCallback callback, Object state)                                                        
          at System.Threading.Tasks.Task.ExecuteWithThreadLocal(Task& currentTaskSlot, Thread threadPoolThread)    
       --- End of stack trace from previous location ---                                                             
          at Microsoft.ApplicationInsights.Profiler.Core.IPC.DuplexNamedPipeService.ConnectAsync(String pipeName, Ca
 ncellationToken cancellationToken)                                                                                  
          at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.<>c__DisplayClass4_0.<<PostStopProc 
 essAsync>b__0>d.MoveNext()                                                                                          
       --- End of stack trace from previous location ---                                                             
          at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.PostStopProcessAsync(PostStopOption 
 s e, CancellationToken cancellationToken)                                                                           
          at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.StopServiceProfilerAsync(IProfilerS 
 ource source, CancellationToken cancellationToken)                                                                
          at Microsoft.ApplicationInsights.Profiler.Core.Orchestration.OrchestratorEventPipe.StopProfilingAsync(SchedulingPolicy policy, CancellationToken cancellationToken)
          at Microsoft.ServiceProfiler.Orchestration.SchedulingPolicy.StartPolicyAsync(CancellationToken cancellatio
 nToken)

Application insight is working fine and are reporting the same exception so I know the instumentationkey is working.

Desktop (please complete the following information):

The instrumentation key is stored in AzureAppConfig and the application is using Workload identity to access it.

I have been searching everywhere for an answer and I just can't figure out why it's not working when AI is working fine.

xiaomi7732 commented 8 months ago

@Eneuman, Thanks for reporting this issue. It looks like this is something new. I will need to spend some time to understand the setup to see if the current implementation is going to work or not:

The instrumentation key is stored in AzureAppConfig and the application is using Workload identity to access it.

When there's an update or if I need more info, I'll post a reply here.

Eneuman commented 8 months ago

The config setup looks like this

  public static IHostBuilder CreateHostBuilder(string[] args) =>
      Host.CreateDefaultBuilder(args)
      .ConfigureAppConfiguration(config =>
      {
        config.AddJsonFile("config/appsettings.json", optional: true);
      })
      .ConfigureWebHostDefaults(webBuilder =>
      webBuilder.ConfigureAppConfiguration((hostingContext, config) =>
      {
        var settings = config.Build();

        config.AddAzureAppConfiguration(options =>
        {
          options.Connect(new Uri(settings["AppConfig:Endpoint"]!), new DefaultAzureCredential());
          options.ConfigureKeyVault(kv =>
          {
            kv.SetCredential(new DefaultAzureCredential());
          });
        });
      })
      .UseStartup<Startup>());
xiaomi7732 commented 8 months ago

Hi @Eneuman ,

I read the callstack, and the error message is: "Could not get the stamp id. Aborting the upload process. ". Based on that, I think you have configured the iKey correctly for the Profiler. Otherwise, it would be something like Please make sure the instrumentation key is valid.

Now, the part I have no clue, about is why the stamp id is not returned properly.

Let's troubleshoot that a bit.

  1. One possible thing is authorization:

    • In the application insights resource, what is the value for the local auth? image
  2. Another possible issue is networking/firewall:

    • Could you please replace the iKey below and try to see if you could hit this endpoint, and what's the response?

      HTTP GET: https://agent.azureserviceprofiler.net/api/profileragent/v4/stampid?iKey=<your-ikey>&machineName=troubleshooting
      • Please try to see if you could curl it within your container to run the app.
  3. It would also help if I can check the backend telemetry. Could you please send over your instrumentation key to serviceprofilerhelp@microsoft.com, mention the url to this issue, and I will be able to look for the telemetries on the requests if they reach our backend.

Thanksl

Eneuman commented 8 months ago

Hi!

Local authentication is enabled.

I think the wget was successfull This is the result:

Connecting to agent.azureserviceprofiler.net (20.100.7.5:443)
Connecting to westeurope.agent.azureserviceprofiler.net:443 (40.113.176.133:443)
saving to 'stampid?iKey=REDACTED&machineName=troubleshooting'
stampid?iKey=REDACTED 100% |************************************************************************|    24  0:00:00 ETA
'stampid?iKey=REDACTED&machineName=troubleshooting' saved

I have mailed you the iKey :)

xiaomi7732 commented 8 months ago

Hi @Eneuman, I got your iKey, but I can't find any related telemetries: image

We did have some high sampling(dropping telemetries) last week. Do you mind run your application again, try to upload the profile a couple of times to see if that works for you? And then I will check the telemetry again.

At the same time, I will need to check something else - maybe it is the uploader that is staled somehow.

Eneuman commented 8 months ago

Hi

I have now send about 15 more gets :)

xiaomi7732 commented 8 months ago

Hey @Eneuman, now I see what is going on, let me explain. According to the telemetry:

image (3)

The profiler client is supposed to follow the redirect (307) automatically, but it isn't. A potential cause is that a newer Azure.Core package that we rely on introduced a break change lately to stop automatically following redirects. That is a known issue. That could explain the behavior (and why wget works). What I am not sure about is what brings in the new version.

Do you mind sharing the project.assets.json in your startup project (after a restore), under the folder of obj? I can do an analysis there to see which one brings in it, and see if there's a potential fix

At the same time, this could be your workaround for now, add a setting to the appsettings.json:

{
    "ServiceProfiler": {
        "Endpoint": "https://westeurope.agent.azureserviceprofiler.net/"
    }
}

Or, in your app configure store, I believe the settings could be formatted as:

ServiceProfiler:Endpoint = https://westeurope.agent.azureserviceprofiler.net/
Eneuman commented 8 months ago

Hi I think you found the problem :) Adding the key to AppConfiguration solved the problem. Here is the file your requested.

Redacted

xiaomi7732 commented 8 months ago

Hey @Eneuman, This is a dependency analysis, Azure.Core is set to 1.35.0 due to multiple dependencies: image

The redirect issue I mentioned was introduced at around 1.33.0. And I think that is why the auto-redirect is disabled.

We have a fix for that in our codebase already. I'll get the beta out soon and let you know.

xiaomi7732 commented 7 months ago

Hi @Eneuman, Please try out the new release and see if that works without the workaround: https://www.nuget.org/packages/Microsoft.ApplicationInsights.Profiler.AspNetCore/2.6.0-beta1

Thanks again for reporting the issue.

KirkMunroSagent commented 6 months ago

What's the ETA on the Microsoft.ApplicationInsights.Profiler.AspNetCore 2.6.0 release with this fix in place?

rasert commented 6 months ago

I am having the same problem and tried the v2.6.0-beta2 but then I got another error just like in this other issue:

[18:51:37 ERR] Trace upload failed. Exit code: 137
[18:51:37 ERR] Unexpected error happens on stopping service profiler.
Microsoft.ApplicationInsights.Profiler.Core.IPC.UnsupportedPayloadTypeException: Can't deserialize message over the named pipe.
   at Microsoft.ApplicationInsights.Profiler.Core.IPC.DuplexNamedPipeService.ReadAsync[T](TimeSpan timeout, CancellationToken cancellationToken)
   at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.<>c__DisplayClass4_0.<<PostStopProcessAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.PostStopProcessAsync(PostStopOptions e, CancellationToken cancellationToken)

[18:51:37 ERR] Unexpected error happens on stopping service profiler tracing.
Microsoft.ApplicationInsights.Profiler.Core.IPC.UnsupportedPayloadTypeException: Can't deserialize message over the named pipe.
   at Microsoft.ApplicationInsights.Profiler.Core.IPC.DuplexNamedPipeService.ReadAsync[T](TimeSpan timeout, CancellationToken cancellationToken)
   at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.<>c__DisplayClass4_0.<<PostStopProcessAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.PostStopProcessAsync(PostStopOptions e, CancellationToken cancellationToken)
   at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.StopServiceProfilerAsync(IProfilerSource source, CancellationToken cancellationToken)

[18:51:37 ERR] Unexpected exception in the last cycle.
Microsoft.ApplicationInsights.Profiler.Core.IPC.UnsupportedPayloadTypeException: Can't deserialize message over the named pipe.
   at Microsoft.ApplicationInsights.Profiler.Core.IPC.DuplexNamedPipeService.ReadAsync[T](TimeSpan timeout, CancellationToken cancellationToken)
   at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.<>c__DisplayClass4_0.<<PostStopProcessAsync>b__0>d.MoveNext()
--- End of stack trace from previous location ---
   at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.PostStopProcessAsync(PostStopOptions e, CancellationToken cancellationToken)
   at Microsoft.ApplicationInsights.Profiler.Core.ServiceProfilerProvider.StopServiceProfilerAsync(IProfilerSource source, CancellationToken cancellationToken)
   at Microsoft.ApplicationInsights.Profiler.Core.Orchestration.OrchestratorEventPipe.StopProfilingAsync(SchedulingPolicy policy, CancellationToken cancellationToken)
   at Microsoft.ServiceProfiler.Orchestration.SchedulingPolicy.StartPolicyAsync(CancellationToken cancellationToken)
bitbound commented 5 months ago

I was having the same issue, and the beta package fixed it for me.

xiaomi7732 commented 5 months ago

Hi @KirkMunroSagent, the release is in the pipe. Expect it by early next week. @bitbound Thanks for the feedback. @rasert I would suggest try it on the 2.6.0 once it is released and if the problem persistent, feel free to file another bug for investigation.

I will post the package info once it is out there.

xiaomi7732 commented 5 months ago

The stable package is released: https://www.nuget.org/packages/Microsoft.ApplicationInsights.Profiler.AspNetCore/2.6.0