aspire icon indicating copy to clipboard operation
aspire copied to clipboard
verified publisher icon dotnet

[Failing test]: Aspire.Hosting.NodeJs.Tests.NodeFunctionalTests.VerifyNpmAppWorks

Open radical opened this issue 8 months ago • 6 comments

Is there an existing issue for this?

  • [x] I have searched the existing issues

Build information

Build: https://github.com/dotnet/aspire/actions/runs/14477929461/job/40608113282 Build error leg or test failing: Aspire.Hosting.NodeJs.Tests.NodeFunctionalTests.VerifyNpmAppWorks Pull Request: N/A

Fill in the error message template

Error Message

Fill the error message using step by step known issues guidance.

{
  "ErrorMessage": "",
  "ErrorPattern": "",
  "BuildRetry": false,
  "ExcludeConsoleLog": false
}

  failed Aspire.Hosting.NodeJs.Tests.NodeFunctionalTests.VerifyNpmAppWorks (0ms)
    Xunit.Runner.InProc.SystemConsole.TestingPlatform.XunitException: Class fixture type 'Aspire.Hosting.NodeJs.Tests.NodeAppFixture' threw in InitializeAsync
    ---- Polly.Timeout.TimeoutRejectedException : The operation didn't complete within the allowed timeout of '00:00:10'.
    -------- System.Threading.Tasks.TaskCanceledException : A task was canceled.
      
      ----- Inner Stack Trace -----
      at Polly.Utils.ExceptionUtilities.TrySetStackTrace[T](T exception)
      at Polly.Timeout.TimeoutResilienceStrategy.ExecuteCore[TResult,TState](Func`3 callback, ResilienceContext context, TState state)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
      at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
      at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
      at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
      at System.Threading.Tasks.Task`1.TrySetResult(TResult result)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result)
      at System.Runtime.CompilerServices.AsyncValueTaskMethodBuilder`1.SetResult(TResult result)
      at Polly.Utils.StrategyHelper.<ExecuteCallbackSafeAsync>g__AwaitTask|0_0[TResult,TState,T](ValueTask`1 task, Boolean continueOnCapturedContext)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
      at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
      at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
      at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
      at System.Threading.Tasks.Task`1.TrySetResult(TResult result)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetExistingTaskResult(Task`1 task, TResult result)
      at System.Runtime.CompilerServices.AsyncValueTaskMethodBuilder`1.SetResult(TResult result)
      at Polly.ResiliencePipeline.<>c.<<ExecuteAsync>b__3_0>d.MoveNext()
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.ExecutionContextCallback(Object s)
      at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext()
      at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
      at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
      at System.Threading.Tasks.Task.TrySetCanceled(CancellationToken tokenToRecord, Object cancellationException)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.SetException(Exception exception, Task`1& taskField)
      at Aspire.Hosting.Dcp.DcpExecutor.<>c__DisplayClass52_0.<<CreateServicesAsync>b__1>d.MoveNext() in /_/src/Aspire.Hosting/Dcp/DcpExecutor.cs:601
      at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
      at Aspire.Hosting.Dcp.KubernetesService.WatchAsync[T](String namespaceParameter, CancellationToken cancellationToken)+MoveNext() in /_/src/Aspire.Hosting/Dcp/KubernetesService.cs:275
      at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
      at Aspire.Hosting.Utils.PeriodicRestartAsyncEnumerable.CreateAsync[T](Func`3 enumerableFactory, TimeSpan restartInterval, CancellationToken cancellationToken)+MoveNext() in /_/src/Aspire.Hosting/Utils/PeriodicRestartAsyncEnumerable.cs:60
      at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
      at k8s.Watcher`1.CreateWatchEventEnumerator(Func`1 streamReaderCreator, Action`1 onError, CancellationToken cancellationToken)+MoveNext()
      at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state)
      at System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1.AsyncStateMachineBox`1.MoveNext(Thread threadPoolThread)
      at System.Threading.Tasks.AwaitTaskContinuation.RunOrScheduleAction(IAsyncStateMachineBox box, Boolean allowInlining)
      at System.Threading.Tasks.Task.RunContinuations(Object continuationObject)
      at System.Threading.Tasks.Task.InternalCancel()
      at System.Threading.CancellationTokenSource.Invoke(Delegate d, Object state, CancellationTokenSource source)
      at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
      at System.Threading.CancellationTokenSource.Invoke(Delegate d, Object state, CancellationTokenSource source)
      at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException)
      at System.Threading.TimerQueueTimer.Fire(Boolean isThreadPool)
      at System.Threading.TimerQueue.FireNextTimers()
      at System.Threading.ThreadPoolWorkQueue.Dispatch()
      at System.Threading.PortableThreadPool.WorkerThread.WorkerThreadStart()
      --- End of stack trace from previous location ---
      at Polly.Outcome`1.GetResultOrRethrow()
      at Polly.ResiliencePipeline.ExecuteAsync(Func`2 callback, CancellationToken cancellationToken)
      at Aspire.Hosting.Dcp.DcpExecutor.CreateServicesAsync(CancellationToken cancellationToken) in /_/src/Aspire.Hosting/Dcp/DcpExecutor.cs:598
      at Aspire.Hosting.Dcp.DcpExecutor.RunApplicationAsync(CancellationToken cancellationToken) in /_/src/Aspire.Hosting/Dcp/DcpExecutor.cs:126
      at Aspire.Hosting.Orchestrator.ApplicationOrchestrator.RunApplicationAsync(CancellationToken cancellationToken) in /_/src/Aspire.Hosting/Orchestrator/ApplicationOrchestrator.cs:295
      at Aspire.Hosting.Orchestrator.OrchestratorHostService.StartAsync(CancellationToken cancellationToken) in /_/src/Aspire.Hosting/Orchestrator/OrchestratorHostService.cs:41
      at Microsoft.Extensions.Hosting.Internal.Host.<StartAsync>b__15_1(IHostedService service, CancellationToken token)
      at Microsoft.Extensions.Hosting.Internal.Host.ForeachService[T](IEnumerable`1 services, CancellationToken token, Boolean concurrent, Boolean abortOnFirstException, List`1 exceptions, Func`3 operation)
      at Microsoft.Extensions.Hosting.Internal.Host.StartAsync(CancellationToken cancellationToken)
      at Aspire.Hosting.DistributedApplication.StartAsync(CancellationToken cancellationToken) in /_/src/Aspire.Hosting/DistributedApplication.cs:369
      at Aspire.Hosting.NodeJs.Tests.NodeAppFixture.InitializeAsync() in /_/tests/Aspire.Hosting.NodeJs.Tests/NodeAppFixture.cs:45
      ----- Inner Stack Trace -----
      at k8s.Watcher`1.CreateWatchEventEnumerator(Func`1 streamReaderCreator, Action`1 onError, CancellationToken cancellationToken)+MoveNext()
      at k8s.Watcher`1.CreateWatchEventEnumerator(Func`1 streamReaderCreator, Action`1 onError, CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult()
      at Aspire.Hosting.Utils.PeriodicRestartAsyncEnumerable.CreateAsync[T](Func`3 enumerableFactory, TimeSpan restartInterval, CancellationToken cancellationToken)+MoveNext() in /_/src/Aspire.Hosting/Utils/PeriodicRestartAsyncEnumerable.cs:39
      at Aspire.Hosting.Utils.PeriodicRestartAsyncEnumerable.CreateAsync[T](Func`3 enumerableFactory, TimeSpan restartInterval, CancellationToken cancellationToken)+MoveNext() in /_/src/Aspire.Hosting/Utils/PeriodicRestartAsyncEnumerable.cs:60
      at Aspire.Hosting.Utils.PeriodicRestartAsyncEnumerable.CreateAsync[T](Func`3 enumerableFactory, TimeSpan restartInterval, CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult()
      at Aspire.Hosting.Dcp.KubernetesService.WatchAsync[T](String namespaceParameter, CancellationToken cancellationToken)+MoveNext() in /_/src/Aspire.Hosting/Dcp/KubernetesService.cs:275
      at Aspire.Hosting.Dcp.KubernetesService.WatchAsync[T](String namespaceParameter, CancellationToken cancellationToken)+MoveNext() in /_/src/Aspire.Hosting/Dcp/KubernetesService.cs:275
      at Aspire.Hosting.Dcp.KubernetesService.WatchAsync[T](String namespaceParameter, CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult()
      at Aspire.Hosting.Dcp.DcpExecutor.<>c__DisplayClass52_0.<<CreateServicesAsync>b__1>d.MoveNext() in /_/src/Aspire.Hosting/Dcp/DcpExecutor.cs:601
      --- End of stack trace from previous location ---
      at Aspire.Hosting.Dcp.DcpExecutor.<>c__DisplayClass52_0.<<CreateServicesAsync>b__1>d.MoveNext() in /_/src/Aspire.Hosting/Dcp/DcpExecutor.cs:601
      --- End of stack trace from previous location ---
      at Polly.ResiliencePipeline.<>c.<<ExecuteAsync>b__3_0>d.MoveNext()

Other info

No response

Report

Summary

24-Hour Hit Count 7-Day Hit Count 1-Month Count
0 0 0

Last 10 failures:

Run date Test Name
Apr 29 6 AM [windows] Aspire.Hosting.NodeJs.Tests.NodeFunctionalTests.VerifyNpmAppWorks
Apr 28 8 AM [windows] Aspire.Hosting.NodeJs.Tests.NodeFunctionalTests.VerifyNpmAppWorks
Apr 26 12 PM [windows] Aspire.Hosting.NodeJs.Tests.NodeFunctionalTests.VerifyNpmAppWorks
Apr 26 10 AM [windows] Aspire.Hosting.NodeJs.Tests.NodeFunctionalTests.VerifyNpmAppWorks
Apr 25 4 PM [windows] Aspire.Hosting.NodeJs.Tests.NodeFunctionalTests.VerifyNpmAppWorks
Apr 25 4 AM [windows] Aspire.Hosting.NodeJs.Tests.NodeFunctionalTests.VerifyNpmAppWorks
Apr 25 2 AM [windows] Aspire.Hosting.NodeJs.Tests.NodeFunctionalTests.VerifyNpmAppWorks
Apr 25 12 AM [windows] Aspire.Hosting.NodeJs.Tests.NodeFunctionalTests.VerifyNpmAppWorks
Apr 24 2 PM [windows] Aspire.Hosting.NodeJs.Tests.NodeFunctionalTests.VerifyNpmAppWorks
Apr 24 8 AM [windows] Aspire.Hosting.NodeJs.Tests.NodeFunctionalTests.VerifyNpmAppWorks

-- Updated on 4/29/2025 6:21:23 PM UTC

Summary

Last 40 Total failed / total runs
2 11 / 157

radical avatar Apr 18 '25 07:04 radical

This is failing regularly on PRs with Xunit.Runner.InProc.SystemConsole.TestingPlatform.XunitException: Class fixture type 'Aspire.Hosting.NodeJs.Tests.NodeAppFixture' threw in InitializeAsync

      at k8s.Watcher`1.CreateWatchEventEnumerator(Func`1 streamReaderCreator, Action`1 onError, CancellationToken cancellationToken)+MoveNext()
      at k8s.Watcher`1.CreateWatchEventEnumerator(Func`1 streamReaderCreator, Action`1 onError, CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult()
      at Aspire.Hosting.Utils.PeriodicRestartAsyncEnumerable.CreateAsync[T](Func`3 enumerableFactory, TimeSpan restartInterval, CancellationToken cancellationToken)+MoveNext() in /_/src/Aspire.Hosting/Utils/PeriodicRestartAsyncEnumerable.cs:39
      at Aspire.Hosting.Utils.PeriodicRestartAsyncEnumerable.CreateAsync[T](Func`3 enumerableFactory, TimeSpan restartInterval, CancellationToken cancellationToken)+MoveNext() in /_/src/Aspire.Hosting/Utils/PeriodicRestartAsyncEnumerable.cs:60
      at Aspire.Hosting.Utils.PeriodicRestartAsyncEnumerable.CreateAsync[T](Func`3 enumerableFactory, TimeSpan restartInterval, CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult()
      at Aspire.Hosting.Dcp.KubernetesService.WatchAsync[T](String namespaceParameter, CancellationToken cancellationToken)+MoveNext() in /_/src/Aspire.Hosting/Dcp/KubernetesService.cs:275
      at Aspire.Hosting.Dcp.KubernetesService.WatchAsync[T](String namespaceParameter, CancellationToken cancellationToken)+MoveNext() in /_/src/Aspire.Hosting/Dcp/KubernetesService.cs:275
      at Aspire.Hosting.Dcp.KubernetesService.WatchAsync[T](String namespaceParameter, CancellationToken cancellationToken)+System.Threading.Tasks.Sources.IValueTaskSource<System.Boolean>.GetResult()
      at Aspire.Hosting.Dcp.DcpExecutor.<>c__DisplayClass52_0.<<CreateServicesAsync>b__1>d.MoveNext() in /_/src/Aspire.Hosting/Dcp/DcpExecutor.cs:601
      --- End of stack trace from previous location ---
      at Aspire.Hosting.Dcp.DcpExecutor.<>c__DisplayClass52_0.<<CreateServicesAsync>b__1>d.MoveNext() in /_/src/Aspire.Hosting/Dcp/DcpExecutor.cs:601

.. which suggests that something failed during the startup.

radical avatar Apr 18 '25 07:04 radical

NodeAppFixture writes its output to diagnosticMessageSink: https://github.com/dotnet/aspire/blob/44630f56ec00181ab87f97f01b045bf553df1514/tests/Aspire.Hosting.NodeJs.Tests/NodeAppFixture.cs#L30-L31

But I can't figure out how to get the output from that. Even using CWL doesn't show up anywhere. If I explicitly write to a file from TestOutputWrapper then I can see the messages. https://github.com/dotnet/aspire/blob/44630f56ec00181ab87f97f01b045bf553df1514/tests/Aspire.Hosting.NodeJs.Tests/NodeAppFixture.cs#L116-L126

But what is the correct way to get these logs? @Youssef1313 @RussKie

radical avatar Apr 18 '25 21:04 radical

I tried /p:VSTestDiag=diag.log also, but that doesn't have the messages logged via the diagnosticMessageSink.

radical avatar Apr 18 '25 21:04 radical

Feels like more of a question for xunit.

Youssef1313 avatar Apr 18 '25 22:04 Youssef1313

According to https://github.com/xunit/xunit/discussions/2391 this is not possible

ITestOutputHelper isn't compatible with any kind of fixture (class or collection). It's possible you're mis-using it in a way that accidentally works. The instance of the test output helper is strongly tied to one specific test, and will fail if you try to use it outside the context of that test.

RussKie avatar Apr 22 '25 02:04 RussKie

According to xunit/xunit#2391 this is not possible

ITestOutputHelper isn't compatible with any kind of fixture (class or collection). It's possible you're mis-using it in a way that accidentally works. The instance of the test output helper is strongly tied to one specific test, and will fail if you try to use it outside the context of that test.

True. That's why we use IMessageSink but I'm not able to get the messages from that out to the diagnostics log file. It would be useful to have the messages from the fixtures logged. We could write to the console but then that just messes up the output. Maybe writing to a file and just emitting the filename to console.

radical avatar Apr 22 '25 07:04 radical

From build:

node:events:502
      throw er; // Unhandled 'error' event
      ^

Error: listen EADDRINUSE: address already in use :::49410
    at Server.setupListenHandle [as _listen2] (node:net:1908:16)
    at listenInCluster (node:net:1965:12)
    at Server.listen (node:net:2067:7)
    at Object.<anonymous> (/private/var/folders/w5/_8wgjw3j5cg6mgrth3s2kg9m0000gn/T/aspire-nodejs-testsZ748IG/app.js:14:8)
    at Module._compile (node:internal/modules/cjs/loader:1529:14)
    at Module._extensions..js (node:internal/modules/cjs/loader:1613:10)
    at Module.load (node:internal/modules/cjs/loader:1275:32)
    at Module._load (node:internal/modules/cjs/loader:1096:12)
    at Function.executeUserEntryPoint [as runMain] (node:internal/modules/run_main:164:12)
    at node:internal/main/run_main_module:28:49
Emitted 'error' event on Server instance at:
    at emitErrorNT (node:net:1944:8)
    at process.processTicksAndRejections (node:internal/process/task_queues:82:21) {
  code: 'EADDRINUSE',
  errno: -48,
  syscall: 'listen',
  address: '::',
  port: 49410
}

Node.js v20.19.0

radical avatar May 29 '25 20:05 radical