Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Combinations of logLevels in host.json can stop function projects starting #7493

Open
1 task done
perfectphase opened this issue Feb 9, 2025 · 3 comments
Open
1 task done
Assignees
Labels
area-integrations Issues pertaining to Aspire Integrations packages azure Issues associated specifically with scenarios tied to using Azure azure-functions Issues related to the Azure Functions integration needs-author-action An issue or pull request that requires more info or actions from the author.
Milestone

Comments

@perfectphase
Copy link

perfectphase commented Feb 9, 2025

Is there an existing issue for this?

  • I have searched the existing issues

Describe the bug

I'm currently in the process of migration one of our solutions to Aspire, it contains a function project that has very high throughput, so has a set of custom log levels in it's host.json. When we try to start the AppHost we end up in this state for a couple of minutes

Image

finally moving to a failed to start state.

Image

Image

Expected Behavior

Function project expected to start regardless of long levels. Or at least with rational 'don't do this' guidelines

Steps To Reproduce

To repo this, we have created a new Aspire starter project from the public template and added a function project (default with timer-based function). We then started the project and ensured that everything started OK.

We then copied the log level section into the new test project's host.json

{
  "version": "2.0",
  "logging": {
    "logLevel": {
      "Function.DeviceChangedIntegrationEventHandler": "Information",
      "Function.DeviceExtraInfoEventHandler": "Information",
      "Function.DeviceStateChanged": "Information",
      "Host.Results": "Information",
      "Host.Aggregator": "Information",
      "Default": "Information",
      "Microsoft": "Warning",
      "System": "Warning",
      "Azure.Messaging.ServiceBus": "Error",
      "Azure.Messaging.EventHubs": "Error"
    },
    "applicationInsights": {
      "samplingSettings": {
        "isEnabled": true,
        "excludedTypes": "Request"
      },
      "enableLiveMetricsFilters": true
    }
  }
}

After that the function host failed to start.

Through trial and error we found that removing the Default entry allows the project to start.

But we also found that this works

{
  "version": "2.0",
  "logging": {
    "logLevel": {
      "Default": "Information",
      "Microsoft": "Warning",
      "System": "Warning"
    },
    "applicationInsights": {
      "samplingSettings": {
        "isEnabled": true,
        "excludedTypes": "Request"
      },
      "enableLiveMetricsFilters": true
    }
  }
}

but this does not

{
  "version": "2.0",
  "logging": {
    "logLevel": {
      "Host.Results": "Information",
      "Host.Aggregator": "Information",
      "Default": "Information",
      "Microsoft": "Warning",
      "System": "Warning"
    },
    "applicationInsights": {
      "samplingSettings": {
        "isEnabled": true,
        "excludedTypes": "Request"
      },
      "enableLiveMetricsFilters": true
    }
  }
}

But this does

{
  "version": "2.0",
  "logging": {
    "logLevel": {
      "Host.Results": "Information",
      "Host.Aggregator": "Information",
      "Default": "Information",
      "Microsoft": "Warning",
      "System": "Warning"
    }
  }
}

and so does this

{
  "version": "2.0",
  "logging": {
    "logLevel": {
      "Host.Results": "Information",
      "Host.Aggregator": "Information"
    },
    "applicationInsights": {
      "samplingSettings": {
        "isEnabled": true,
        "excludedTypes": "Request"
      },
      "enableLiveMetricsFilters": true
    }
  }
}

In all cases the project starts correctly if launched directly rather than via aspire

So there must be some combination but have no idea on what the root cause is

Exceptions (if any)

After several minutes:

fail: Aspire.Hosting.Dcp.dcpctrl.ExecutableReconciler[0]
timeout of 120 seconds exceeded waiting for the IDE to start a run session; you can set the DCP_IDE_REQUEST_TIMEOUT_SECONDS environment variable to override this timeout (in seconds) {"Executable": {"name":"functionapp1-rvrnqgmb"}, "Reconciliation": 7, "error": "Put "https://localhost:50213/run_session?api-version=2024-04-23\": context deadline exceeded"}

.NET Version info

Versions: .net 9.0, aspire 9.0, functions 9.0.0-preview.5.24551.3, VS:17.12.4

Also tried on daily builds of 9.1 with same outcome.

Anything else?

startup log with "Aspire.Hosting.Dcp": "Trace"

info: Aspire.Hosting.DistributedApplication[0]
      Aspire version: 9.0.0+01ed51919f8df692ececce51048a140615dc759d
info: Aspire.Hosting.DistributedApplication[0]
      Distributed application starting.
info: Aspire.Hosting.DistributedApplication[0]
      Application host directory is: D:\Repos\tmp\AspireApp2\AspireApp2.AppHost
info: Aspire.Hosting.Dcp.DcpHostService[0]
      Starting DCP with arguments: start-apiserver --monitor 15008 --detach --kubeconfig "C:\Users\stephen\AppData\Local\Temp\aspire.d2jjyilu.r0v\kubeconfig"
dbug: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Watching over DCP Container resources.
dbug: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Watching over DCP Service resources.
dbug: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Watching over DCP Endpoint resources.
dbug: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Watching over DCP Executable resources.
info: Aspire.Hosting.Dcp.start-apiserver.api-server[0]
      Starting API server...
info: Aspire.Hosting.Dcp.start-apiserver.api-server[0]
      API server started        {"Address": "::1", "Port": 56021}
info: Aspire.Hosting.Dcp.start-apiserver.dcp-host[0]
      Starting DCP controller host
info: Aspire.Hosting.Dcp.start-apiserver.dcp-host[0]
      Started all services      {"count": 1}
info: Aspire.Hosting.Dcp.dcpctrl.ContainerOrchestrator[0]
      runtime status    {"ContainerRuntime": "", "runtime": "podman", "status": {"Installed":false,"Running":false,"Error":"exec: \"podman\": executable file not found in %PATH%\nfailed to start podman command 'Info'"}}
info: Aspire.Hosting.Dcp.dcpctrl.ContainerOrchestrator[0]
      runtime status    {"ContainerRuntime": "", "runtime": "docker", "status": {"Installed":true,"Running":true,"Error":""}}
info: Aspire.Hosting.Dcp.dcpctrl[0]
      starting controller manager
dbug: Aspire.Hosting.Dcp.KubernetesService[0]
      Successfully read Kubernetes configuration from 'C:\Users\stephen\AppData\Local\Temp\aspire.d2jjyilu.r0v\kubeconfig' after 1303 milliseconds.
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource cache with Container resource cache-jmtkmcfh
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource cache with Container resource cache-jmtkmcfh
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource cache with Container resource cache-jmtkmcfh
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource cache with Container resource cache-jmtkmcfh
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource funcstorage10ef1 with Container resource funcstorage10ef1-adpqxyzy
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource funcstorage10ef1 with Container resource funcstorage10ef1-adpqxyzy
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource funcstorage10ef1 with Container resource funcstorage10ef1-adpqxyzy
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource funcstorage10ef1 with Container resource funcstorage10ef1-adpqxyzy
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource apiservice with Executable resource apiservice-hufxkyca
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource apiservice with Executable resource apiservice-hufxkyca
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource apiservice with Executable resource apiservice-hufxkyca
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource functionapp1 with Executable resource functionapp1-qptxwkmp
info: Aspire.Hosting.DistributedApplication[0]
      Now listening on: https://localhost:17242
info: Aspire.Hosting.DistributedApplication[0]
      Login to the dashboard at https://localhost:17242/login?t=bbaebced4ae130105dcc552cbec68456
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource aspire-dashboard with Executable resource aspire-dashboard-fqmggsrb
info: Aspire.Hosting.Dcp.dcpctrl.ServiceReconciler[0]
      service /apiservice-https is now in state Ready   {"ServiceName": {"name":"apiservice-https"}, "Reconciliation": 28}
info: Aspire.Hosting.Dcp.dcpctrl.ServiceReconciler[0]
      service /apiservice-http is now in state Ready    {"ServiceName": {"name":"apiservice-http"}, "Reconciliation": 29}
info: Aspire.Hosting.Dcp.dcpctrl.ExecutableReconciler[0]
      starting process...       {"Executable": {"name":"aspire-dashboard-fqmggsrb"}, "Reconciliation": 8, "executable": "C:\\Users\\stephen\\.nuget\\packages\\aspire.dashboard.sdk.win-x64\\9.0.0\\tools\\Aspire.Dashboard.exe"}
info: Aspire.Hosting.Dcp.dcpctrl.ExecutableReconciler[0]
      process started   {"Executable": {"name":"aspire-dashboard-fqmggsrb"}, "Reconciliation": 8, "executable": "C:\\Users\\stephen\\.nuget\\packages\\aspire.dashboard.sdk.win-x64\\9.0.0\\tools\\Aspire.Dashboard.exe", "PID": 31436}
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource apiservice with Executable resource apiservice-hufxkyca
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource functionapp1 with Executable resource functionapp1-qptxwkmp
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource aspire-dashboard with Executable resource aspire-dashboard-fqmggsrb
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource apiservice with Executable resource apiservice-hufxkyca
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource functionapp1 with Executable resource functionapp1-qptxwkmp
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource aspire-dashboard with Executable resource aspire-dashboard-fqmggsrb
dbug: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Starting log streaming for aspire-dashboard-fqmggsrb.
info: Aspire.Hosting.Dcp.dcpctrl.NetworkReconciler[0]
      network created   {"NetworkName": {"name":"default-aspire-network"}, "Reconciliation": 2, "Network": "default-aspire-network-ffc2v6flsg"}
info: Aspire.Hosting.Dcp.dcpctrl.ContainerReconciler[0]
      Added new ContainerNetworkConnection      {"Container": {"name":"cache-jmtkmcfh"}, "Reconciliation": 9, "Container": "eb951792305d4ad718e8d0b704d7698f592194fea73ae3b1c1d2e2e91dc55cb2", "ContainerNetworkConnection": "/cache-jmtkmcfh-default-aspire-network-4nqdrjpm04"}
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource cache with Container resource cache-jmtkmcfh
info: Aspire.Hosting.Dcp.dcpctrl.ContainerReconciler[0]
      Added new ContainerNetworkConnection      {"Container": {"name":"funcstorage10ef1-adpqxyzy"}, "Reconciliation": 10, "Container": "dc00cfa41c4f0a1fdabb70acc615a93c786a6606022f304002e49be6f78148ca", "ContainerNetworkConnection": "/funcstorage10ef1-adpqxyzy-default-aspire-network-1342cn89so"}
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource funcstorage10ef1 with Container resource funcstorage10ef1-adpqxyzy
info: Aspire.Hosting.Dcp.dcpctrl.NetworkReconciler[0]
      connected a container to the network      {"NetworkName": {"name":"default-aspire-network"}, "Reconciliation": 4, "Container": "eb951792305d4ad718e8d0b704d7698f592194fea73ae3b1c1d2e2e91dc55cb2", "Network": "default-aspire-network-ffc2v6flsg"}
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource cache with Container resource cache-jmtkmcfh
info: Aspire.Hosting.Dcp.dcpctrl.NetworkReconciler[0]
      connected a container to the network      {"NetworkName": {"name":"default-aspire-network"}, "Reconciliation": 5, "Container": "dc00cfa41c4f0a1fdabb70acc615a93c786a6606022f304002e49be6f78148ca", "Network": "default-aspire-network-ffc2v6flsg"}
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource funcstorage10ef1 with Container resource funcstorage10ef1-adpqxyzy
info: Aspire.Hosting.Dcp.dcpctrl.ServiceReconciler[0]
      service /cache is now in state Ready      {"ServiceName": {"name":"cache"}, "Reconciliation": 32}
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource webfrontend with Executable resource webfrontend-qhajcvbn
info: Aspire.Hosting.DistributedApplication[0]
      Distributed application started. Press Ctrl+C to shut down.
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource cache with Container resource cache-jmtkmcfh
info: Aspire.Hosting.Dcp.dcpctrl.ServiceReconciler[0]
      service /funcstorage10ef1-blob is now in state Ready      {"ServiceName": {"name":"funcstorage10ef1-blob"}, "Reconciliation": 34}
info: Aspire.Hosting.Dcp.dcpctrl.ServiceReconciler[0]
      service /funcstorage10ef1-queue is now in state Ready     {"ServiceName": {"name":"funcstorage10ef1-queue"}, "Reconciliation": 36}
info: Aspire.Hosting.Dcp.dcpctrl.ServiceReconciler[0]
      service /funcstorage10ef1-table is now in state Ready     {"ServiceName": {"name":"funcstorage10ef1-table"}, "Reconciliation": 38}
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource funcstorage10ef1 with Container resource funcstorage10ef1-adpqxyzy
fail: Aspire.Hosting.Dcp.dcpctrl.ExecutableReconciler[0]
      timeout of 120 seconds exceeded waiting for the IDE to start a run session; you can set the DCP_IDE_REQUEST_TIMEOUT_SECONDS environment variable to override this timeout (in seconds)       {"Executable": {"name":"functionapp1-qptxwkmp"}, "Reconciliation": 7, "error": "Put \"https://localhost:50213/run_session?api-version=2024-04-23\": context deadline exceeded"}
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource functionapp1 with Executable resource functionapp1-qptxwkmp
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource webfrontend with Executable resource webfrontend-qhajcvbn
trce: Aspire.Hosting.Dcp.ApplicationExecutor[0]
      Updating application model resource webfrontend with Executable resource webfrontend-qhajcvbn
@perfectphase
Copy link
Author

For got to add, that it always works when you run without debugging

@davidfowl davidfowl added area-integrations Issues pertaining to Aspire Integrations packages azure Issues associated specifically with scenarios tied to using Azure azure-functions Issues related to the Azure Functions integration untriaged labels Feb 9, 2025
@sebastienros sebastienros added this to the Backlog milestone Feb 11, 2025
@captainsafia
Copy link
Member

captainsafia commented Feb 14, 2025

@perfectphase Thanks for filing this issue!

What version of Visual Studio are you using? This bug report seems related to #6660 which was resolved in 17.13 Preview 4.

EDIT: I missed that you included the version in the configuration details. It seems like you are on 17.12? Can you trying 17.13 Preview 4 to help us confirm if this is the same as the other bug?

@captainsafia captainsafia added the needs-author-action An issue or pull request that requires more info or actions from the author. label Feb 14, 2025
Copy link

This submission has been automatically marked as stale because it has been marked as requiring author action but has not had any activity for 14 days.
It will be closed if no further activity occurs within 7 days of this comment.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area-integrations Issues pertaining to Aspire Integrations packages azure Issues associated specifically with scenarios tied to using Azure azure-functions Issues related to the Azure Functions integration needs-author-action An issue or pull request that requires more info or actions from the author.
Projects
None yet
Development

No branches or pull requests

5 participants