Test failure: CacheTagHelper_AllowsVaryingByUICulture and CacheTagHelper_VaryByCultureComposesWithOtherVaryByOptions

[ryanbrandenburg]

This test fails occasionally with the following error:

Assert.Equal() Failure
           ↓ (pos 1)
Expected: 10
Actual:   14
           ↑ (pos 1)
   at Microsoft.AspNetCore.Mvc.FunctionalTests.HtmlGenerationWithCultureTest.CacheTagHelper_VaryByCultureComposesWithOtherVaryByOptions() in /_/test/Microsoft.AspNetCore.Mvc.FunctionalTests/HtmlGenerationWithCultureTest.cs:line 152
--- End of stack trace from previous location where exception was thrown ---

Other tests within that build may have failed with a similar message, but they are not listed here. Check the link above for more info.

This test failed on 2.2.

CC @mkArtakMSFT

This issue was made automatically. If there is a problem contact ryanbrandenburg.

[ryanbrandenburg]

Please use this workflow to address this flaky test issue, including checking applicable checkboxes and filling in the applicable "TODO" entries:

• Is this actually a flaky test?

  • No, this is a regular test failure, fix the test/product (TODO: Link to commit/PR)
  • Yes, proceed below...

• Is this test failure caused by product code flakiness? (Either this product, or another product this test depends on.)

  • [ ] File a bug against the product (TODO: Link to other bug)
  • Is it possible to change the test to avoid the flakiness?
  • Yes? Go to the "Change the test!" section.
  • No?
    • [ ] Disable the test (TODO: Link to PR/commit)
    • [ ] Wait for other bug to be resolved
    • [ ] Wait for us to get build that has the fix
    • [ ] Re-enable our test (TODO: Link to PR/commit)
    • [ ] Close this bug

• Is it that the test itself is flaky? This includes external transient problems (e.g. remote server problems, file system race condition, etc.)

  • Is there is a way to change our test to avoid this flakiness?
  • Yes? Change the test!
    • [ ] Change the test to avoid the flakiness, for example by using a different test strategy, or by adding retries w/ timeouts (TODO: Link to PR/commit)
    • [ ] Run the test 100 times locally as a sanity check.
    • [ ] Close this bug
  • No?
    • Is there any logging or extra information that we could add to make this more diagnosable when it happens again?
    • Yes?
      • [x] Add the logging https://github.com/aspnet/Mvc/pull/8294
    • No?
      • [ ] Delete the test because flaky tests are not useful (TODO: Link to PR/commit)

This comment was made automatically. If there is a problem contact ryanbrandenburg.

[mkArtakMSFT]

@NTaylorMullen, can you please look into this? Thanks!

[NTaylorMullen]

Adding logging. @mkArtakMSFT @ryanbrandenburg how should I label this issue while we wait for more test failures with added logging?

[ryanbrandenburg]

Personally I would say:

1. Label it blocked.
2. Wait a couple days to see if it happens again. a. If it happens again use your new logs to figure out what's up. b. If it doesn't close the bug for now, the bot will open a new one when it happens.

@Eilon in case he wants to countermand that workflow. We might work that into the checklist if it's unclear.

[aspnet-hello]

CacheTagHelper_VaryByCultureComposesWithOtherVaryByOptions failed with about the same error on master.

This comment was made automatically. If there is a problem contact ryanbrandenburg.

[Eilon]

@NTaylorMullen is this the same failure as before? Does the new logging provide useful info?

[NTaylorMullen]

@NTaylorMullen is this the same failure as before? Does the new logging provide useful info?

Well it ruled out the one cause I thought possible 😲 . Now I gotta consider other possibilities.

[aspnet-hello]

There were 1 failures with about the same error on master:

• CacheTagHelper_VaryByCultureComposesWithOtherVaryByOptions

This comment was made automatically. If there is a problem contact ryanbrandenburg.

[Eilon]

@NTaylorMullen - I see one MVC failure on the latest run:

[17:45:45] :     [Step 3/3]   Mvc                   |   [xUnit.net 00:00:39.36]     Microsoft.AspNetCore.Mvc.FunctionalTests.HtmlGenerationWithCultureTest.CacheTagHelper_VaryByCultureComposesWithOtherVaryByOptions [FAIL]
[17:45:45] :     [Step 3/3]   Mvc                   |   Failed   Microsoft.AspNetCore.Mvc.FunctionalTests.HtmlGenerationWithCultureTest.CacheTagHelper_VaryByCultureComposesWithOtherVaryByOptions
[17:45:45] :     [Step 3/3]   Mvc                   |   Error Message:
[17:45:45] :     [Step 3/3]   Mvc                   |    Unexpected correlation Id, reading values from document:
[17:45:45] :     [Step 3/3]   Mvc                   |   <html><head></head><body><h2 id="culture">fr-FR</h2>
[17:45:45] :     [Step 3/3]   Mvc                   |   <h2 id="ui-culture">fr-FR</h2>
[17:45:45] :     [Step 3/3]   Mvc                   |   <span id="correlation-id">14</span>
[17:45:45] :     [Step 3/3]   Mvc                   |   
[17:45:45] :     [Step 3/3]   Mvc                   |       <span id="cached-correlation-id">14</span>
[17:45:45] :     [Step 3/3]   Mvc                   |   
[17:45:45] :     [Step 3/3]   Mvc                   |   </body></html>
[17:45:45] :     [Step 3/3]   Mvc                   |   Stack Trace:
[17:45:45] :     [Step 3/3]   Mvc                   |      at Microsoft.AspNetCore.Mvc.FunctionalTests.HtmlGenerationWithCultureTest.CacheTagHelper_VaryByCultureComposesWithOtherVaryByOptions() in /_/test/Microsoft.AspNetCore.Mvc.FunctionalTests/HtmlGenerationWithCultureTest.cs:line 163
[17:45:45] :     [Step 3/3]   Mvc                   |   --- End of stack trace from previous location where exception was thrown ---

...

[18:04:15] :     [Step 3/3]   SignalR               |         Finished test ServerThrowsHubExceptionOnStreamingHubMethodArgumentCountMismatch_messagepack_LongPolling_default in 0.0258653s
[18:04:16] :     [Step 3/3]   SignalR               |   System.Exception: Failed to bind Stream Item arguments to proper type.
[18:04:16] :     [Step 3/3]   SignalR               |      at System.Threading.Channels.AsyncOperation`1.GetResult(Int16 token)
[18:04:16] :     [Step 3/3]   SignalR               |      at System.Threading.Tasks.ValueTask`1.get_Result()
[18:04:16] :     [Step 3/3]   SignalR               |      at Microsoft.AspNetCore.SignalR.Tests.MethodHub.TestTypeCastingErrors(ChannelReader`1 source) in /_/test/Microsoft.AspNetCore.SignalR.Tests/HubConnectionHandlerTestUtils/Hubs.cs:line 231
[18:04:18] :     [Step 3/3]   SignalR               |   [xUnit.net 00:00:11.49]     Microsoft.AspNetCore.SignalR.Redis.Tests.RedisEndToEndTests.CanSendAndReceiveUserMessagesFromMultipleConnectionsWithSameUser(transportType: LongPolling, protocolName: "json") [FAIL]
[18:04:18] :     [Step 3/3]   SignalR               |   Failed   Microsoft.AspNetCore.SignalR.Redis.Tests.RedisEndToEndTests.CanSendAndReceiveUserMessagesFromMultipleConnectionsWithSameUser(transportType: LongPolling, protocolName: "json")
[18:04:18] :     [Step 3/3]   SignalR               |   Error Message:
[18:04:18] :     [Step 3/3]   SignalR               |    System.TimeoutException : Operation in CanSendAndReceiveUserMessagesFromMultipleConnectionsWithSameUser timed out at /_/test/Microsoft.AspNetCore.SignalR.Redis.Tests/RedisEndToEnd.cs:118
[18:04:18] :     [Step 3/3]   SignalR               |   Stack Trace:
[18:04:18] :     [Step 3/3]   SignalR               |      at System.Threading.Tasks.TaskExtensions.OrTimeout[T](Task`1 task, TimeSpan timeout, String memberName, String filePath, Nullable`1 lineNumber) in /_/test/Microsoft.AspNetCore.SignalR.Tests.Utils/TaskExtensions.cs:line 67
[18:04:18] :     [Step 3/3]   SignalR               |      at Microsoft.AspNetCore.SignalR.Redis.Tests.RedisEndToEndTests.CanSendAndReceiveUserMessagesFromMultipleConnectionsWithSameUser(HttpTransportType transportType, String protocolName) in /_/test/Microsoft.AspNetCore.SignalR.Redis.Tests/RedisEndToEnd.cs:line 118
[18:04:18] :     [Step 3/3]   SignalR               |   --- End of stack trace from previous location where exception was thrown ---

And @anurse , I'm also seeing a bunch of these SignalR + Redis failures:

[18:05:04]E:         [VSTest] Runner error: [xUnit.net 00:00:31.73]     Microsoft.AspNetCore.SignalR.Redis.Tests.RedisEndToEndTests.CanSendAndReceiveUserMessagesFromMultipleConnectionsWithSameUser(transportType: LongPolling, protocolName: "messagepack") [FAIL]

@anurse - any idea on that?

[BrennanConroy]

@Eilon Those are filed on SignalR by the bot

[Eilon]

Ah OK so just @NTaylorMullen needs to look at the MVC stuff.

[mkArtakMSFT]

@NTaylorMullen, is this test still failing?

[NTaylorMullen]

Last failure was a while ago but I wrote some code in MVC to make it possible to diagnose why it's failing. I've seen it fail twice but it is uncommon. My bet is that it's still flakey, just not as flakey as some of our other flakey tests that we've seen in the past. I'd vote for leaving this open a while longer

[NTaylorMullen]

Ah, actually this is a duplicate. Tracking this here: https://github.com/aspnet/AspNetCore-Internal/issues/1337

[halter73]

We got a new test failure here:

Error message:

Unexpected correlation Id, reading values from document:

<html><head></head><body>
fr-FR

fr-FR

14
<span id="cached-correlation-id">14</span>

</body></html>

Stack trace:

   at Microsoft.AspNetCore.Mvc.FunctionalTests.HtmlGenerationWithCultureTest.CacheTagHelper_VaryByCultureComposesWithOtherVaryByOptions() in /_/src/Mvc/test/Mvc.FunctionalTests/HtmlGenerationWithCultureTest.cs:line 171
--- End of stack trace from previous location ---

https://dev.azure.com/dnceng-public/public/_build/results?buildId=655364&view=ms.vss-test-web.build-test-results-tab&runId=16222964&resultId=124372&paneView=debug

A clue here is that 5 other tests failed with 100 second HttpClient timeouts, so the CI server was clearly running slower than normal. I think that the CacheTagHelper.DefaultExpiration of 30 seconds is to blame.

[halter73]

See #55930 for more details on the very similar CacheTagHelper_AllowsVaryingByUICulture failure.