[13.0] Container Tunnel fails to start.

[afscrome]

Is there an existing issue for this?

• I have searched the existing issues

Describe the bug

In 13.0.0-preview.1.25558.3 (which I believe is latest at the time of writing), Trying to start my apphost with ASPIRE_ENABLE_CONTAINER_TUNNEL set in launch settings causes the App Host to hang before the dashboard shows up.

If I look in docker desktop, I can see an aspire-container-network-tunnelproxy resource briefly show up, but it almost immediately exists. I have tried to capture logs for this, but the container gets deleted almost instantly before I can capture them.

Expected Behavior

1. I expect the tunnel to start, and for hte app host to follow
2. If the tunnel does fail to start, I'd expect some kind of error to be forwarded to the app host, and the app host to throw an exception almost immediately rather than hanging indefinitely.

Steps To Reproduce

info: Aspire.Hosting.DistributedApplication[0]
      Aspire version: 13.0.0-preview.1.25558.3+b420c735e38d4fc22cf9bebfafc952308d68c5ff
info: Aspire.Hosting.DistributedApplication[0]
      Distributed application starting.
info: Aspire.Hosting.DistributedApplication[0]
      Application host directory is: S:\Trayport.Aspire\src\Trayport.Aspire.AppHost
info: Aspire.Hosting.Dcp.DcpHost[0]
      Starting DCP with arguments: start-apiserver --monitor 51088 --detach --kubeconfig "C:\Users\alexanderc\AppData\Local\Temp\aspire.zqcbrogd.kub\kubeconfig"
dbug: Aspire.Hosting.Dcp.DcpExecutor[0]
      Watching over DCP Endpoint resources.
dbug: Aspire.Hosting.Dcp.DcpExecutor[0]
      Watching over DCP Executable resources.
dbug: Aspire.Hosting.Dcp.DcpExecutor[0]
      Watching over DCP Container resources.
dbug: Aspire.Hosting.Dcp.DcpExecutor[0]
      Watching over DCP ContainerExec resources.
dbug: Aspire.Hosting.Dcp.DcpExecutor[0]
      Watching over DCP Service resources.
dbug: Aspire.Hosting.Dcp.dcp.start-apiserver.api-server[0]
      Starting API server...
dbug: Aspire.Hosting.Dcp.dcp.start-apiserver.api-server[0]
      API server started        {"Address": "127.0.0.1", "Port": 54819}
dbug: Aspire.Hosting.Dcp.dcp.start-apiserver.dcp-host[0]
      Starting DCP controller host
dbug: Aspire.Hosting.Dcp.dcp.start-apiserver.dcp-host[0]
      Started all services      {"count": 1}
dbug: Aspire.Hosting.Dcp.KubernetesService[0]
      Successfully read Kubernetes configuration from 'C:\Users\alexanderc\AppData\Local\Temp\aspire.zqcbrogd.kub\kubeconfig' after 1170 milliseconds.
dbug: Aspire.Hosting.Dcp.dcpctrl[0]
      Starting controller manager
info: Aspire.Hosting.Dcp.DcpExecutor[0]
      Waiting for container network 'aspire-container-network' tunnel initialization...
dbug: Aspire.Hosting.Dcp.dcpctrl.dcpctrl.NetworkReconciler[0]
      Network created   {"ContainerNetwork": "/aspire-container-network", "Reconciliation": 2, "NetworkName": "aspire-session-network-yeemfcxr-Trayport.Aspire"}
dbug: Aspire.Hosting.Dcp.dcpctrl.dcpctrl.NetworkReconciler[0]
      All expected containers are connected to the network      {"ContainerNetwork": "/aspire-container-network", "Reconciliation": 4, "NetworkName": "aspire-session-network-yeemfcxr-Trayport.Aspire", "NetworkID": "4a57ce157386", "Expected": 1, "Found": 1}
dbug: Aspire.Hosting.Dcp.dcpctrl.dcpctrl.TunnelProxyReconciler[0]
      No more ContainerNetworkTunnelProxy resources are being watched, cancelling container watch       {"ContainerNetworkTunnelProxy": "/aspire-container-network-tunnelproxy", "Reconciliation": 6}
dbug: Aspire.Hosting.Dcp.dcpctrl.dcpctrl.os-executor[0]
      Context expired, stopping process...      {"PID": 29272, "Command": "C:\\Program Files\\Docker\\Docker\\resources\\bin\\docker.exe", "Args": ["events", "--filter", "type=container", "--format", "{{json .}}"]}
dbug: Aspire.Hosting.Dcp.dcpctrl.dcpctrl.os-executor[0]
      Root process has stopped  {"Root": 29272}
dbug: Aspire.Hosting.Dcp.dcpproc.dcpproc.ProcessMonitor[0]
      Monitor process exited, shutting down     {"MonitorPID": 49668, "ChildPID": 29272, "PID": 29272}

Exceptions (if any)

No response

.NET Version info

No response

Anything else?

No response

[afscrome]

cc @danegsta

Curiously, after several attempts the tunnel (and the rest of the app host) started up for me. But only that one time, I haven't been able to get it to start up since. I was able to capture DCP logs for this successful run though, which could be compared to the failed runs Logs.zip.

I also have logs here for running a test. I get this same error both locally, and in a pipeline on a linux agent under Azure Devops.

    20:23:56.033] dbug: Microsoft.Extensions.Hosting.Internal.Host[1]
      Hosting starting
20:23:56.074] info: Aspire.Hosting.DistributedApplication[0]
      Aspire version: 13.0.0-preview.1.25558.3+b420c735e38d4fc22cf9bebfafc952308d68c5ff
20:23:56.075] info: Aspire.Hosting.DistributedApplication[0]
      Distributed application starting.
20:23:56.075] info: Aspire.Hosting.DistributedApplication[0]
      Application host directory is: S:\Trayport.Aspire\src\Trayport.Aspire.AppHost.Tests
20:23:56.079] dbug: Aspire.Hosting.Cli.BackchannelService[0]
      Backchannel socket path was not specified.
20:23:56.464] info: Aspire.Hosting.Dcp.DcpHost[0]
      Starting DCP with arguments: start-apiserver --monitor 17992 --detach --kubeconfig "C:\Users\alexanderc\AppData\Local\Temp\aspire.copzmqwe.nim\kubeconfig"
20:23:56.565] dbug: Aspire.Hosting.Dcp.DcpExecutor[0]
      Watching over DCP Endpoint resources.
20:23:56.565] dbug: Aspire.Hosting.Dcp.DcpExecutor[0]
      Watching over DCP Executable resources.
20:23:56.565] dbug: Aspire.Hosting.Dcp.DcpExecutor[0]
      Watching over DCP Container resources.
20:23:56.565] dbug: Aspire.Hosting.Dcp.DcpExecutor[0]
      Watching over DCP ContainerExec resources.
20:23:56.565] dbug: Aspire.Hosting.Dcp.DcpExecutor[0]
      Watching over DCP Service resources.
20:23:57.162] dbug: Aspire.Hosting.Dcp.dcp.start-apiserver.api-server[0]
      Starting API server...
20:23:57.187] dbug: Aspire.Hosting.Dcp.dcp.start-apiserver.api-server[0]
      API server started	{"Address": "127.0.0.1", "Port": 65148}
20:23:57.187] dbug: Aspire.Hosting.Dcp.dcp.start-apiserver.dcp-host[0]
      Starting DCP controller host
20:23:57.187] dbug: Aspire.Hosting.Dcp.dcp.start-apiserver.dcp-host[0]
      Started all services	{"count": 1}
20:23:57.543] dbug: Aspire.Hosting.Dcp.KubernetesService[0]
      Successfully read Kubernetes configuration from 'C:\Users\alexanderc\AppData\Local\Temp\aspire.copzmqwe.nim\kubeconfig' after 956 milliseconds.
20:23:57.616] dbug: Aspire.Hosting.Dcp.dcpctrl[0]
      Starting controller manager
20:23:57.883] info: Aspire.Hosting.Dcp.DcpExecutor[0]
      Waiting for container network 'aspire-container-network' tunnel initialization...
20:23:58.596] dbug: Aspire.Hosting.Dcp.dcpctrl.dcpctrl.NetworkReconciler[0]
      Network created	{"ContainerNetwork": "/aspire-container-network", "Reconciliation": 2, "NetworkName": "aspire-session-network-qwtzmdqm-Trayport.Aspire.AppHost.Tests"}
20:24:02.443] dbug: Aspire.Hosting.Dcp.dcpctrl.dcpctrl.NetworkReconciler[0]
      All expected containers are connected to the network	{"ContainerNetwork": "/aspire-container-network", "Reconciliation": 4, "NetworkName": "aspire-session-network-qwtzmdqm-Trayport.Aspire.AppHost.Tests", "NetworkID": "641cfc85ddc6", "Expected": 1, "Found": 1}
20:24:04.058] dbug: Aspire.Hosting.Dcp.dcpctrl.dcpctrl.TunnelProxyReconciler[0]
      No more ContainerNetworkTunnelProxy resources are being watched, cancelling container watch	{"ContainerNetworkTunnelProxy": "/aspire-container-network-tunnelproxy", "Reconciliation": 6}
20:24:04.058] dbug: Aspire.Hosting.Dcp.dcpctrl.dcpctrl.os-executor[0]
      Context expired, stopping process...	{"PID": 12028, "Command": "C:\\Program Files\\Docker\\Docker\\resources\\bin\\docker.exe", "Args": ["events", "--filter", "type=container", "--format", "{{json .}}"]}
20:24:04.131] dbug: Aspire.Hosting.Dcp.dcpctrl.dcpctrl.os-executor[0]
      Root process has stopped	{"Root": 12028}
20:24:04.135] dbug: Aspire.Hosting.Dcp.dcpproc.dcpproc.ProcessMonitor[0]
      Monitor process exited, shutting down	{"MonitorPID": 50692, "ChildPID": 12028, "PID": 12028}
20:24:25.887] dbug: Aspire.Hosting.Dcp.DcpExecutor[0]
      Watching for service port allocation ended with an error after 28001.1043 (iteration 0)
      System.Threading.Tasks.TaskCanceledException: A task was canceled.
         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:line 39
         at Aspire.Hosting.Utils.PeriodicRestartAsyncEnumerable.CreateAsync[T](Func`3 enumerableFactory, TimeSpan restartInterval, CancellationToken cancellationToken)+MoveNext() in /_/src/Aspire.Hosting/Utils/PeriodicRestartAsyncEnumerable.cs:line 59
         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:line 298
         at Aspire.Hosting.Dcp.KubernetesService.WatchAsync[T](String namespaceParameter, CancellationToken cancellationToken)+MoveNext() in /_/src/Aspire.Hosting/Dcp/KubernetesService.cs:line 298
         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__DisplayClass57_0.<<UpdateWithEffectiveAddressInfo>b__0>d.MoveNext() in /_/src/Aspire.Hosting/Dcp/DcpExecutor.cs:line 781
      --- End of stack trace from previous location ---
         at Aspire.Hosting.Dcp.DcpExecutor.<>c__DisplayClass57_0.<<UpdateWithEffectiveAddressInfo>b__0>d.MoveNext() in /_/src/Aspire.Hosting/Dcp/DcpExecutor.cs:line 781
      --- End of stack trace from previous location ---
         at Polly.ResiliencePipeline.<>c.<<ExecuteAsync>b__3_0>d.MoveNext()
20:24:25.895] dbug: Aspire.Hosting.Dcp.DcpExecutor[0]
      Cancellation received during application startup.
20:24:25.896] info: Aspire.Hosting.DistributedApplication[0]
      Distributed application started. Press Ctrl+C to shut down.
20:24:25.896] dbug: Microsoft.Extensions.Hosting.Internal.Host[2]
      Hosting started
20:24:25.898] dbug: Aspire.Hosting.ApplicationModel.ResourceNotificationService[0]
      Waiting for resource 'prometheusMetricsAdapter' to enter the 'Healthy' state.