Google-cloud-dotnet: Tracing does not work well in Cloud Run with TimedBuffer

[EatonZ]

I have a Cloud Run service behind Cloud Load Balancer. The service is a .NET Core API, utilizing this library to log traces.

If I send 5 concurrent requests, only one gets traced. This is confirmed by checking the Trace List in the Cloud Console, and also the HTTP responses - only the first response has a X-Cloud-Trace-Context header. If I send the 5 requests, but wait for the previous one to complete before sending the next, all 5 get traced. I looked through the options and I tried specifying BufferOptions.NoBuffer() in UseGoogleDiagnostics, but that didn't seem to make a difference. Am I missing something, or could this be a bug?

[jskeet]

We'll look at this on Tuesday - Monday is a public holiday in the UK.

[amanda-tarafa]

@EatonZ Can you provide a minimum but full application that reproduces the problem for you? We do have some tests around concurrent tracing and logging and they seem to work.

[EatonZ]

@amanda-tarafa Here you go. It's a lot (sorry!), but it does reproduce the problem.

Please make sure you have gcloud installed and authenticated. You should also have the latest PowerShell. The built-in Windows version may not work. Finally, make sure Docker Desktop is installed and running.

1. Download pack and copy beside the .sln file.
2. Create a new GCP project so you can easily dispose of everything when done. Enable the Run and Compute APIs, and create an Artifact Registry repo named ez-sample.
3. Open GoogleBuild.ps1 in Notepad, put in your project ID at the top, and create/put in a service account (give it the Cloud Trace Agent role).
4. In GoogleCreateLoadBalancer.ps1, put in your project ID at the top.
5. Create an IP here. Premium, IPv4, Global, named ez-sample-ip.
6. Run these 2 commands:
   gcloud auth configure-docker "us-docker.pkg.dev"
gcloud auth print-access-token | docker login --username "oauth2accesstoken" --password-stdin "https://us-docker.pkg.dev"
7. Run GoogleCreateLoadBalancer.ps1 and GoogleBuild.ps1. It may get stuck on _Adding label 'io.buildpacks.project.metadata'_ for a while the first time - just wait it out. Once both finish successfully, wait a few minutes for the load balancer to fully set up.
8. Use Fiddler, Postman, or whatever to send 5 HTTP (not HTTPS) requests concurrently to https://[ez-sample-ip]/hello. There are 2 problems you should see. First, when you send the first batch of 5 requests to wake the Cloud Run service, all the responses have a X-Cloud-Trace-Context header, but nothing shows in Trace List. When you send a second batch of 5 requests, only the first one will have a X-Cloud-Trace-Context header, and it will show in Trace List.

If you look at the project, I am using a third-party REST framework. I couldn't use FromServicesAttribute per your example, so they gave me a solution and it works, just not concurrently. Not sure if the bug is with your library or theirs.

Thank you in advance for taking a look!

[amanda-tarafa]

@EatonZ this is far from a simple project and what's really a problem for me tu use it to help you diagnose is the several external dependencies, we don't have control over what those do, don't have the code, don't have experience with those, etc. So, let's try to simplify this so I can actually try and use it to confirm or not whether there's a problem with the Diagnostics libraries.

We have many integration tests that either rely on or explicitly test concurrent tracing and all of those are passing as expected. You can see one of those here. Mind you, I'm not saying there's no problem, I'm just saying that I'm pretty certain that concurrent tracing works well for most cases.
It would be good if you started from a stripped down ASP.NET Core 3 project, with just the Diagnostics dependency, no docker, etc. and build from there. Test with each of the individual pieces separately and if all keeps working, then start mixing dependencies in pairs, etc. I understand this is cumbersome, but it's really the only way to get the minimum application that reproduces the problem which is really what we need to properly diagnose.

Also, a couple of things you can try inmediately:

• Configure tracing as described in Troubleshooting Tracing. You create the trace options in the same way as described there and pass them to the UseGoogleDiagnostics() call.
  
  
  
  • It's possible that you are not seing all the traces because the buffer hasn't flushed when you look.
  
  
  • It's possible that there's an exception being thrown by tracing, by default we don't propagate exceptions because we believe we shouldn't break an application if tracing fails.
  
  
• In the same trace options set the qps to double.PositiveInfinity to make sure that all requests are traced. It's possible that you are not seing all the traces because of the default qps value.

My gut feeling is that this has to do with the custom framework you are using. We support and depend on ASP.NET Core 3, if that custom framework is in any way modifying or intercepting the standard ASP.NET Core 3 pipeline, then I wouldn't be surprised if tracing doesn't work properly. The fact that you can't use ASP.NET Core 3 standard dependency injection mechanism makes think that they are, indeed, intercepting the standard pipeline.

[EatonZ]

@amanda-tarafa Thanks for your in-depth reply!

I have done some testing today and have uncovered interesting results.

I solved the problem where the trace header wasn't being added to my 5 responses. I needed to set qpsSampleRate to double.PositiveInfinity. I thought the default, 1.0, meant trace everything like it does in other GCP configurations, but that was not the case here. Oops.

The second problem is where the traces do not appear in the Trace List. This one is a bit harder to pin down. It seems that on Cloud Run container start, the trace method calls cause the sandbox to crash, and each HTTP request ends up taking 3-4 seconds longer than usual (due to the sandbox restarting after crashing, I presume). Due to the crash, the traces are not recorded in Trace List. The crash log is shown in Cloud Run logs:

I am still experimenting and may have more to add later.

[EatonZ]

It appears that simply adding UseGoogleDiagnostics is the minimum to make the sandbox start crashing, and it's not limited to container start, but that's when it happens most frequently.

[EatonZ]

Alright, I can confirm the problem is reproducible in a standard ASP.NET Core web app, not using any third party libraries besides yours.

Here is the download
To reproduce:

1. Build/deploy to Cloud Run. Use GCP buildpacks to make it easy.
2. Initiate 5 requests to /hello in quick succession.
3. Each response will have a trace header, but will not show in your project's Trace List.
4. Cloud Run logs will mention the membarrier issue.
5. At this point, send 1 more request, and this one will go through just fine and be traced.

Please note that this reproduces most of the time, but not all of the time. If the 5 requests are traced successfully, redeploy the container to make the service cold again, and then retry.

[amanda-tarafa]

That's definitely something I can work with. I'll take a look on Monday and report here as soon as I know more.

[EatonZ]

@amanda-tarafa Great! One more thing for you, here is a video showing the exact behavior. This is using the sample app I uploaded for you.

1. I initiate 5 HTTPS requests to my domain (which maps to the Cloud Load Balancer, and then to the Cloud Run service).
2. Each of those 5 requests takes a long time (note the TTFB column). This appears to be due to the membarrier crash, which you see on the left that I click on. None of these 5 are put into the Trace List. I suppose the crash occurs before your buffer has time to flush.
3. I send 1 more request after the dust has settled, and it goes through timely, and is properly traced pretty much instantly.

[amanda-tarafa]

Just a heads up, a couple other things have come up, but this is still on my TODO for this week. I won't be looking at it today though.

[amanda-tarafa]

So, I've been trying to reproduce this issue for a lot of the afternoon and I haven't been able to.

1. I used the buildpacks to build my image from your source code, with no changes: pack build --builder=gcr.io/buildpacks/builder web-hello
2. I tagged and uploaded the web-hello image to my GCP project:
   docker tag web-hello gcr.io/<my-gcp-project>/web-hello docker push gcr.io/<my-gcp-project>/web-hello
3. On the Cloud Run home page I clicked on Create Service and left everything on default execpt for:
   
   
   
   • The region: I used europe-west1.
   
   
   • I entered a service name of course.
   
   
   • I used the image created and pushed on the previous steps.
   
   
   • I allowed unauthenticated invocations.
   
   
4. For retrying, I redeployed a new revision with no changes every time I needed.
5. I wrote a small app that sends 5, 10, 15, 20 requests to the endpoint and each time attempts to obtain the traces it expects. I ran the app 10 times right after the service was deployed.
   
   
   
   • All requests were successfull and took at most a 1300ms, which is not that much given that you are waiting for 900ms in your code.
   
   
   • All traces were written as expected.
   
   
6. I then ran my app again, 10 times again, but this time I didn't wait for the service to finished deploying.
   
   
   
   • In this scenario the only difference is that the requests took longer overal, around 2.5 seconds, which is normal because they had to wait for the service to finish deploying. All the requests were succesfull all the time and all the traces were correctly written.
   
   

I did encounter the membarrier error in the logs, but it leterally says:

"Container Sandbox: Unsupported syscall membarrier(0x0,0x0,0x1b,0x0,0x0,0x1). It is very likely that you can safely ignore this message and that this is not the cause of any error you might be troubleshooting. Please, refer to https://gvisor.dev/c/linux/amd64/membarrier for more information."

So, a few questions for you:

• Are you doing anything different? If so, which step from above and what is the difference?
• In your last comment you mention that you have a Cloud Load Balancer, can you try without it?
• Does the membarrier error message is the same as mine, or is it something less harmless?

[EatonZ]

I wrote a small app that sends 5, 10, 15, 20 requests to the endpoint and each time attempts to obtain the traces it expects. I ran the app 10 times right after the service was deployed.

Are you sending them all at once, like seen in my example video?

Are you doing anything different? If so, which step from above and what is the difference?

You are pushing the Docker image different (I use pack's --publish), but that should not matter.

In your last comment you mention that you have a Cloud Load Balancer, can you try without it?

Just did, still happens.

Does the membarrier error message is the same as mine, or is it something less harmless?

It's the same.

All requests were successfull and took at most a 1300ms

This is what sticks out to me. It seems like your service could already be warm before you send requests to it? After you deploy the new service, don't send any requests to it until you send the test requests.

[amanda-tarafa]

I wrote a small app that sends 5, 10, 15, 20 requests to the endpoint and each time attempts to obtain the traces it expects. I ran the app 10 times right after the service was deployed.

Are you sending them all at once, like seen in my example video?

As much as the computer allows me to ;). But yes, separate tasks. And in any case I also tried with fiddler, sending several at a time and with Chrome, hitting F5 :). All worked.

Are you doing anything different? If so, which step from above and what is the difference?

You are pushing the Docker image different (I use pack's --publish), but that should not matter.

I agree it shouldn't matter, I'll still try pack's publish tomorrow, just in case.

All requests were successfull and took at most a 1300ms

This is what sticks out to me. It seems like your service could already be warm before you send requests to it? After you deploy the new service, don't send any requests to it until you send the test requests.

I'm not sending anything before the test requests. On step 5 I just wait for the service to finish deploying. On step 6 I don't even wait for it to be deployed and although requests take longer (as expected), they still go through successfully and the traces are there.

[EatonZ]

I'm not quite sure why you can't reproduce, but I would like to try a different approach.
I would like to log the result of the call to the GCP PatchTraces API you are doing internally in the library. I don't see any errors in my Cloud Console, so this is really just logging to make sure the API call actually went through. Since 1 API call can have multiple traces, logging the trace IDs would be good too. This way, I can confirm whether this library is actually sending the trace data, or not.
Two questions before I try that:

1. Is there any internal logging functionality anywhere that would output that information?
2. If #1 is no, where would be the best spot to insert such logging code?

[amanda-tarafa]

You can enable gRPC logging and see whether the calls go through or not.

[amanda-tarafa]

A couple other things you can look at:

• To check whether your application is crashing before the diagnostics buffer is flushed, configure tracing to have no buffer and to propagate exceptions as well as shown here Troubleshooting Tracing. If the problem is that it crashes before the buffer is flushed then at least some of the traces should get through. And if the problem is that we are silently catching some exception, then by propagating it the application should really crash and it should show on logs.

• When you don't see the traces, do you at least see log entries representing the requests (when you click on the Logs tab on the Service Details page and then click on the top right icon to see the logs on the Logs Viewer). Something like this:
  

  If you expand any of those, they should have a trace property, and the last part of the value is the trace ID. If you copy that ID and paste it on the Trace List page where you can select a trace by ID, does the trace show even if it doesn't show on the list? Wait for an hour or two and try again. If I remember correctly, 90% of trace entries are guarateed to be available in seconds, 95% in minutes, and the rest at some point.

• Also, about the application crashing, do you see any evidence of that in the Cloud Run logs. I believe that should be there somehow.

[EatonZ]

I am still testing, but I wanted to share some results now.

I tried BufferOptions.NoBuffer(). It works _so much better_. All traces logged consistently, and they show up pretty much instantly in Trace list.

BufferOptions.TimedBuffer just does not seem to work well. Either I see no traces, or they trickle in Trace list very slowly, and I often do not see all of them.

So far, I see no exceptions when ExceptionHandling.Propagate is used in any case.

[EatonZ]

To answer your questions:

If you expand any of those, they should have a trace property, and the last part of the value is the trace ID. If you copy that ID and paste it on the Trace List page where you can select a trace by ID, does the trace show even if it doesn't show on the list? Wait for an hour or two and try again

Logs always show up fine. I plugged in some trace IDs in the logs from yesterday (almost 24 hours ago) and Trace list says they still do not exist. Out of 7 logs from a batch I sent yesterday, only 1 trace ID actually exists. Very strange.

Also, about the application crashing, do you see any evidence of that in the Cloud Run logs. I believe that should be there somehow.

Nothing more than the membarrier issue. However, I figured out the reason I saw a lot of them. It's the cloud run max instances. If I set that to 1, I will only see 1 log. At this point I am not sure if that is related to the problem.

Looking into gRPC logging now and will provide another comment in a bit.

[EatonZ]

Thank you for the gRPC logging link. I set the following Cloud Run environment variables:

GRPC_TRACE=http
GRPC_VERBOSITY=DEBUG

It looks like we are on the right track. Here's a portion of the logs that seem interesting:

The requests I send show in the logs timestamped 18:20:21.
The "Deadline Exceeded" errors start at timestamp 18:21:12 (almost a minute later!) I am leaving TimedBuffer's flush time at 5 seconds.
That explains the "slow trickle" of traces I see, and this is probably why some eventually time out and do not get reported at all.
When sending some requests after the cold start, they show in Trace list pretty quick, and the logs have none of these errors.

What do you suggest?

[amanda-tarafa]

OK, that's progress, my thoughts:

• The Diagnostics library is sending all traces, but we are getting a transport timeout.
• The timeout happens on gRPC requests to the Trace API from your CloudRun app, not from mine.
• It only seems to happen when a buffer is involved, it works well without a buffer, in which each trace is sent individually.

Conclusions from this:

• The problem has nothing to do with concurrent tracing.
• The problem is related to the size of the request, when traces are buffered and flushed, they are all sent at the same time.
• The problem is in the environment, which is supported by the fact that I never could reproduce.
  
  
  
  • My environment can handle at least 20 buffered requests, yours can't, for some unknown reason.
  
  

Things to try:

• With timed buffers, tweaking the wait time, send 2 request only, then 3, etc. See what gets throught and what doesn't. This is just mostly to confirm. You seem to want to trace everything and if your environment is slow in getting through to the Trace API, you won't be able to use a timed buffer. Maybe a sized buffer with a max size set to what you confirm gets through will work.
• Figure out why your CloudRun environment is having trouble reaching the Trace API with "big" requests. This one is tricky. I can help here by telling you how mine is set up so you can compare, but not much else.
  
  
  
  • It might be related to region.
  
  
  • It might be related to how you have set up your CloudRun and services, with load balancers, etc.
  
  
  • It might be related to some of your project's settings.
  
  
  • If you can start with a project from scratch and just run the clean code that you sent me, using the buildpacks as they are etc., that might help you figure out what the problem might be.
  
  
  • Also, consider creating an issue on the Trace Public Issue tracker.
  
  

I will revisit the code and tests for the buffers, just to make extra certain that everything is fine, but I don't expect to find anything there to be honest. We haven't made any changes to that code in a long time, tests has been passing and there hasn't been any issue reported around it.

Let me know if you think there's something else we can do on our side.

[EatonZ]

The problem is in the environment, which is supported by the fact that I never could reproduce.

If you enable gRPC logging, do you see the same errors in your logs? In my tests the traces eventually went through, but were significantly delayed.

With timed buffers, tweaking the wait time, send 2 request only, then 3, etc. See what gets throught and what doesn't.

I will play around with it...

I can help here by telling you how mine is set up so you can compare, but not much else.

Could the Linux distribution that is being used by buildpacks cause a problem like this in gRPC?
Also, is there a way to force the library to send non-gRPC requests?

[amanda-tarafa]

The problem is in the environment, which is supported by the fact that I never could reproduce.

If you enable gRPC logging, do you see the same errors in your logs? In my tests the traces eventually went through, but were significantly delayed.

No, nothing in the logs. And also, my traces show almost inmediately, the default wait time for the timed buffer is 5s, so that's fine.

I can help here by telling you how mine is set up so you can compare, but not much else.

Could the Linux distribution that is being used by buildpacks cause a problem like this in gRPC?

Yes, I suppose it could, but then why didn't I see it? There's a known issue with Alpine and gRPC, but it's a proper crash, nothing like this.

Also, is there a way to force the library to send non-gRPC requests?

Not at the moment, no.

[EatonZ]

No, nothing in the logs. And also, my traces show almost inmediately, the default wait time for the timed buffer is 5s, so that's fine.

I just tried setting TimedBuffer all the way down to 1 second. Surprisingly, it didn't help at all.
Would you mind giving us-east1 a try on your end? That is what I am using. Perhaps you can reproduce there.

There's a known issue with Alpine and gRPC, but it's a proper crash, nothing like this.

That bug doesn't seem to apply here, I see _gRPC native library loaded successfully_.

Figure out why your CloudRun environment is having trouble reaching the Trace API with "big" requests.

Let me give you a new observation.

Using the default TimedBuffer - sending just 1 request. Waited several minutes and nothing in Trace list. Deadline Exceeded error observed in logs, and here is the important part: There is a 40 second difference between the autogenerated Cloud Run request log and the first gRPC debug log.

Using NoBuffer - sending just 1 request. Trace appears practically instantly in Trace list. There is a less than 1 second difference between the autogenerated Cloud Run request log and the first gRPC debug log. The gRPC debug log entry is the same one as seen when using TimedBuffer.

This is important for 2 reasons:

1. TimedBuffer struggles just sending 1 trace. It doesn't have to be a big request with multiple traces.
2. For some reason, TimedBuffer starts attempting to log the trace at a time that is much later than what is configured.

A good place to start looking for a bug seems to be the code that kicks off the TimedBuffer gRPC request. I don't think it should be taking 40 seconds to start.

The problem has nothing to do with concurrent tracing.

Indeed - title updated.🙂

[amanda-tarafa]

No, nothing in the logs. And also, my traces show almost inmediately, the default wait time for the timed buffer is 5s, so that's fine.

I just tried setting TimedBuffer all the way down to 1 second. Surprisingly, it didn't help at all.
Would you mind giving us-east1 a try on your end? That is what I am using. Perhaps you can reproduce there.

I tried us-east1, as soon as I send the requests I switch to the trace tabs, and there they are, all of them, a couple of the requests take a little over 1s just because the service is really warming up:

I am using your code, which except for tracing every request, sets everything by default, which means that I'm using the TimedBuffer with a wait time of 5 seconds. I'm using the same image I built with the buildpacks as I described in one of my earliest comments, and I'm not changing any of the default values when creating the Cloud Run service. I send requests with the service still being deployed and also after, everything works just fine.

Figure out why your CloudRun environment is having trouble reaching the Trace API with "big" requests.

Let me give you a new observation.

Using the default TimedBuffer - sending just 1 request. Waited several minutes and nothing in Trace list. Deadline Exceeded error observed in logs, and here is the important part: There is a 40 second difference between the autogenerated Cloud Run request log and the first gRPC debug log.

Using NoBuffer - sending just 1 request. Trace appears practically instantly in Trace list. There is a less than 1 second difference between the autogenerated Cloud Run request log and the first gRPC debug log. The gRPC debug log entry is the same one as seen when using TimedBuffer.

What is the exact gRPC log entry?

This is important for 2 reasons:

1. TimedBuffer struggles just sending 1 trace. It doesn't have to be a big request with multiple traces.
2. For some reason, TimedBuffer starts attempting to log the trace at a time that is much later than what is configured.

A good place to start looking for a bug seems to be the code that kicks off the TimedBuffer gRPC request. I don't think it should be taking 40 seconds to start.

The TimedBuffer depends on System.Threading.Timer if that's not triggering at the right time, there's something else going on almost certainly.
The gRPC deadline is also happening, and the gRPC call is no different if it comes from the TimedBuffer or from no buffer (or at least it shouldn't be) so, also, there seems to be something else happening.
My point is, the TimedBuffer might be the cause of the problem, or just sensitive to whatever else is happening.

A few questions/other things to try. Sorry for passing this on to you, but I can't reproduce.

• I suppose there are no differences between the apps and environments that use the TimedBuffer and no buffer. Just double check please. Also I suppose that you are sending the no buffer traces with a cold app.
• The app with the TimedBuffer, when it warms up, are there still issues, either with the traces not showing or in the gRPC logs?
• Can you try with a SizedBuffer as well? Set the buffer size "small" so only one trace gets in.

I will revisit the buffers and tests next week and see if there's something there. I will probably end up writing some more tests at least.

[EatonZ]

Update: No longer relevant - see comment below.

To rule out some things, I created a new project and re-tested.

I deployed the sample app to Cloud Run (us-east1). I may not have mentioned it before, but I use these additional flags:
--cpu=2 --memory="4Gi" --timeout=30
You may want to use those settings too so we're on the same page.

To be fully transparent, these are the 2 commands I use to deploy:

1. pack build --builder "gcr.io/buildpacks/builder:v1" --env GOOGLE_BUILDABLE="$MAIN_CSPROJ_DIR" --publish "us-docker.pkg.dev/$PROJECT_ID/$SERVICE_NAME/$SERVICE_NAME"
2. gcloud run deploy "$SERVICE_NAME" --image="us-docker.pkg.dev/$PROJECT_ID/$SERVICE_NAME/$($SERVICE_NAME):latest" --cpu=2 --memory="4Gi" --platform="managed" --service-account="$SERVICE_ACCOUNT" --timeout=30 --allow-unauthenticated --region="$PRIMARY_REGION" --project="$PROJECT_ID" --quiet

Aside from setting the gRPC debug variables manually, there is nothing else I am doing.

Calling /hello results in the following:

1. A nearly 40 second delay between the request log and the first gRPC debug log.
2. Many Deadline Exceeded errors.

My suggestion for your next test:

1. Deploy using updated flags mentioned above.
2. Set gRPC debug vars: GRPC_TRACE=http, GRPC_VERBOSITY=DEBUG
3. Check for log time difference between last request log and the first gRPC debug log.

Answers to questions in your post coming in my next reply...

[EatonZ]

Update: No longer relevant - see comment below.

What is the exact gRPC log entry?

See below. You can see the time difference too. Note that some numeric values in the string may change, so it may not match what you see 100%.

My point is, the TimedBuffer might be the cause of the problem, or just sensitive to whatever else is happening.

I think a good way to proceed is to learn why the TimedBuffer starts so late. You should be able to see that easily in the logs when you have the gRPC debug vars set.

I suppose there are no differences between the apps and environments that use the TimedBuffer and no buffer. Just double check please. Also I suppose that you are sending the no buffer traces with a cold app.

I am using the sample app I uploaded. I outlined potential differences in my previous reply. The cold start is important. You may not be seeing what I am because you aren't getting cold starts. If the requests take less than 2 seconds, it isn't a cold start. It's unclear how to force a cold start (a redeploy may not work for some reason😕).

The app with the TimedBuffer, when it warms up, are there still issues, either with the traces not showing or in the gRPC logs?

Once warm (sending requests a few minutes after the first batch):

1. Traces show up instantly.
2. There is no ~40 second delay. All the gRPC debug logs after the last request log happen within the next 1-2 seconds.

Can you try with a SizedBuffer as well? Set the buffer size "small" so only one trace gets in.

Tried with size 1 and it seems to work fine.

[EatonZ]

@amanda-tarafa You may just want to consider disregarding everything I have written above and just focus on the below.

At this point I believe I have found the most likely culprit: the CPU.
Official Cloud Run docs state that you should not do anything after the request has finished. Since TimedBuffer is clearly designed to process _after_ the request, it makes total sense why it can really chug along and take up to 40 seconds to actually start processing, only to run into errors due to extremely limited CPU.

Relevant StackOverflow question.

It makes sense now why NoBuffer works great. Unfortunately, it adds time to my request since it's no longer a background task...

With all that in mind, I think we can rule out any bugs in google-cloud-dotnet. However, since TimedBuffer is the default, I think something needs to be done for Cloud Run users - TimedBuffer should not be used in this environment at all.
The solution I am thinking of (at least for me) is to use a SizedBuffer of int.MaxValue to prevent sending right away. Then, in AssemblyLoadContext.Default.Unloading (SIGTERM), flush the buffer. What is the proper way to flush a SizedBuffer?
Unfortunately, this solution will not be perfect. It isn't possible to determine when SIGTERM will happen. It could happen in minutes, or more than 24 hours, so this can cause a significant delay in sending traces, and also potential problems in sending if the buffer ends up being huge. There is also a chance the SizedBuffer size may also be reached, so maybe a better solution would be to add a new buffer type... maybe "CloudRunBuffer", which could have special handling for Cloud Run environments.

[amanda-tarafa]

Official Cloud Run docs state that you should not do anything after the request has finished. Since TimedBuffer is clearly designed to process _after_ the request, it makes total sense why it can really chug along and take up to 40 seconds to actually start processing, only to run into errors due to extremely limited CPU.

Relevant StackOverflow question.

OK, this explains everything, (and makes total sense btw), including the gRPC timeouts and the fact that I couldn't reproduce (probably because I wasn't scaling down my CPUs).

It makes sense now why NoBuffer works great. Unfortunately, it adds time to my request since it's no longer a background task...

Is the added time relevant? That of course depends on your context, but just check, it might be that it just adds .1% to the total time of the request and that's acceptable for you.

With all that in mind, I think we can rule out any bugs in google-cloud-dotnet. However, since TimedBuffer is the default, I think something needs to be done for Cloud Run users - TimedBuffer should not be used in this environment at all.

I will ad a note in the docs linking to proper documentation and advising not to use TimedBuffer when running in CloudRun or similar environments. We can't change the default now and risk breaking everyone else, and I feel that configuring one or the other type of buffer is straightforward.

The solution I am thinking of (at least for me) is to use a SizedBuffer of int.MaxValue to prevent sending right away.

That means that if the buffer gets full, you'd be looking at a little over 2Gb of memory. I would really advise you to use a smaller value, even if it means adding some overhead to a few requests to flush along the way. I'm pretty sure requests will get really slow way before you are buffering that many traces anyway. And also notice that gRPC has limits on message received size, and the wire itself might complain as well.

Then, in AssemblyLoadContext.Default.Unloading (SIGTERM), flush the buffer. What is the proper way to flush a SizedBuffer?

You don't need to flush the buffer explicitly, it will be flushed on Dispose which will happen before SIGTERM.

Unfortunately, this solution will not be perfect. It isn't possible to determine when SIGTERM will happen. It could happen in minutes, or more than 24 hours, so this can cause a significant delay in sending traces, and also potential problems in sending if the buffer ends up being huge.

You still won't know when Dispose will be called so you can still see delays on traces. Or problems depending on the size of the buffer. But again I would encourage you to pick a smaller buffer size, because by the time you are seeing problems sending traces on Dispose because of the buffer size, your latest requests were already, almost certainly, very slow if responsive at all.

There is also a chance the SizedBuffer size may also be reached

If the buffer size is reached, it will be flushed, will affect the particular request that made it go over.

so maybe a better solution would be to add a new buffer type... maybe "CloudRunBuffer", which could have special handling for Cloud Run environments.

We almost certainly won't do that, our implementation would run into the same or similar issues as you are describing because it needs to be CloudRun who supports some sort of background work, which probably goes against CloudRun "spirit" in any case.

My advice would be to use no buffer or SizedBuffer and play around with the numbers until the overhead you see is acceptable. Maybe also consider just sampling traces instead of tracing everything, etc. I understand this is not ideal but I believe it's the best that can be done in environments that, by definition, won't properly handle background work, which is not restricted to CloudRun by the way.

[EatonZ]

Is the added time relevant? That of course depends on your context, but just check, it might be that it just adds .1% to the total time of the request and that's acceptable for you.

Very much. It can add a lot of latency to request handling, but most importantly, there will be gaps in the trace report.

I think I have some up with a solution, but I need to know how to manually flush the trace buffer. Can you tell me how?

I will make a Cloud Scheduler task to hit a request URL dedicated to flushing traces.
I will also add SIGTERM handling to do a final flush of the traces.

The flushing needs to be done in the request, where the CPU is most available, and this seems to be the only way to do that without affecting the real requests.

[amanda-tarafa]

There's no way that you can manually flush the buffer right now. I could expose something via standard dependency injection that would allow you to, from a request. I don't think it will available on SIGTERM handling though and I wouldn't do any explicit work for that to be available on SIGTERM. I really really think you don't need to handle SIGTERM and at that point we won't guarantee that the Diagnostics library works, some of our dependencies or even our own objects might have been disposed off at that point, etc. All the buffers will flush on Dispose, and Dispose will happen before the application is shut down.

About your solution though, I think it won't solve your problems, you don't know which of the Cloud Run instances your special request will hit, there's no guarantee on the distribution of those hits across your instances, etc. So, you will almost certainly will see delays in tracing, will run into the same problems re the buffer being very big and getting very full if for some reason one of the instances is never hit, etc.

The problem here is that you really want to do something that it's not supported by the environment you are running in.

[EatonZ]

Hm, you are right, my workaround will not work.😫

There doesn't appear to be a good solution here. Just due to the nature of Cloud Run, NoBuffer needs to be used, but that will slow down the request a bit. I suppose that reducing the sample rate will be a compromise to stop it from making _all_ requests slower.

Unless you have anything to add, I believe that NoBuffer with a reduced sample rate may be the most "correct" option.

Still, you should definitely add some extra documentation for Cloud Run so others do not run into the same situation I did.

[amanda-tarafa]

I think you can also try SizedBuffer and play a little with the numbers until you find a sweet spot between the latency it adds to the request that makes the buffer go over, the amount of traces you want to sample and the amount of requests that remain unaffected. That is of course if you are fine with not getting traces immediately.

Also, have you tried not using the Diagnostics library and writing to stdout? I think that should be captured before the CPUs are spun down and send to Google Logging by Cloud Run without affecting the request. It won't be traces though, it'll be logs.

I will add some docs around this by the end of the week. I'll leave this issue open just for that.

[EatonZ]

I think you can also try SizedBuffer and play a little with the numbers until you find a sweet spot between the latency it adds to the request that makes the buffer go over, the amount of traces you want to sample and the amount of requests that remain unaffected. That is of course if you are fine with not getting traces immediately.

That is indeed an option, still a risk that on low-traffic days, the instance will terminate before the size is reached.

Also, have you tried not using the Diagnostics library and writing to stdout?

Yes, no problems there. I don't have any logging to do at the moment, though - just tracing.

I will add some docs around this by the end of the week. I'll leave this issue open just for that.

I agree - I don't think there is anything else that can be done right now. Maybe in the future Cloud Run will change something to open up more workarounds. I'll let you know if that ever happens.🙂

[EatonZ]

What I have decided to do is disable aspnetcore tracing and just keep logging and error reporting. In cases where that needs to happen, I will tolerate the small amount of added latency added by NoBuffer.

However, when logging, it doesn't set the trace ID in LogEntry now since tracing is no longer enabled. Is it possible to override that? The trace ID is there, and it comes from the load balancer.
Basically, I do not want the library to generate a trace span, so that is why I disabled it. However, I'd still like logs/errors to have the trace ID set, if possible (so they will be organized in the GCP console). Let me know if that makes sense.

[amanda-tarafa]

Yes, there's a way to do that. If you don't activate Tracing we do assume that you don't want trace information in logs but it's easy to bring that back in.
You have to implement Google.Cloud.Diagnostics.AspNetCore.IExternalHeaderProvider, you can even user our own helper clases to extract the trace and span IDs from the header by using Google.Cloud.Diagnostics.Common.TraceHeaderContext.FromHeader.
You then add a dependency to your implementation on your startup class (or similar), like such, we look for this dependency when creating logs and using to fill in the trace information if any.

public virtual void ConfigureServices(IServiceCollection services)
{
    ...
    services.AddSingleton<IExternalTraceProvider>(new BringBackTheTraceTraceProvider());
}

Remember that the load balancer is only sampling (at least mine was only sampling) so you will still see logs without the tracing info, because in that case there's none.

[EatonZ]

Thanks for the tip. Got it working with this code. Had to search for a way to get the header value. Is there a simpler way or am I correct?

private sealed class AddTraceDetailsProvider : IExternalTraceProvider
{
    public TraceContextForLogEntry GetCurrentTraceContext(IServiceProvider serviceProvider)
    {
        if (serviceProvider.GetService<IHttpContextAccessor>().HttpContext.Request.Headers.TryGetValue(TraceHeaderContext.TraceHeader, out var traceHeaderValue))
        {
            var traceHeaderContext = TraceHeaderContext.FromHeader(traceHeaderValue);
            return new TraceContextForLogEntry(traceHeaderContext.TraceId, $"{traceHeaderContext.SpanId:x16}");
        }
        else return null;
    }
}

Can trace/span IDs be attached to exception logs too or is that not how they work?

[amanda-tarafa]

That's about right, except that the span format should be string.Format("0x{0:X}", spanId).
Actually, if you wait for a few days, I can add this into the library, seems reasonable.

Can trace/span IDs be attached to exception logs too or is that not how they work?

I don't inmediately see why not. I'll take a closer look and get back to you.

[amanda-tarafa]

(I just saw #5355 on span ID format, commenting there).

[EatonZ]

Thanks for your work on all this. I am glad this discussion resulted in several improvements being made.😁

When will you publish a new version to NuGet?

[amanda-tarafa]

Probably tomorrow. I want CI to run fully tonight before publishing, just in case. And it will be a beta for a couple of weeks until we've gotten some usage, at least from you ;), and confirm everything is as expected.

The couple of pending features, will still be one or two weeks away.