Skip to content

Startup is not being invoked #7430

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.

Sign up for GitHub

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

Jump to bottom
Closed
mmulhearn opened this issue Jun 3, 2021 · 6 comments
Closed

Startup is not being invoked #7430

mmulhearn opened this issue Jun 3, 2021 · 6 comments

Comments

@mmulhearn
Copy link

This is a continuation of #5401, but for Microsoft.NET.Sdk.Functions v3.0.12. Downgrading to v3.0.3 or v3.0.5, as found as the fix for #5401, also does not fix the issue.

Using Visual Studio Code, my startup file is not being invoked even though the logs seem to indicate the process is aware of the startup file. I am running this locally and debugging and my breakpoints are not being hit, neither on warmup nor on the first request.

Core Tools Version:       3.0.3568 Commit hash: e30a0ede85fd498199c28ad699ab2548593f759b  (64-bit)
Function Runtime Version: 3.0.15828.0

.csproj

<Project Sdk="Microsoft.NET.Sdk">
  <PropertyGroup>
    <TargetFramework>netcoreapp3.1</TargetFramework>
    <AzureFunctionsVersion>v3</AzureFunctionsVersion>
    <RootNamespace>mock_backend</RootNamespace>
  </PropertyGroup>
  <ItemGroup>
    <PackageReference Include="microsoft.azure.functions.extensions" Version="1.1.0" />
    <PackageReference Include="Microsoft.NET.Sdk.Functions" Version="3.0.12" />
  </ItemGroup>
  <ItemGroup>
    <None Update="host.json">
      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
    </None>
    <None Update="local.settings.json">
      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
      <CopyToPublishDirectory>Never</CopyToPublishDirectory>
    </None>
    <None Update="mockResponses\getUpdates\newChat.json">
      <CopyToOutputDirectory>PreserveNewest</CopyToOutputDirectory>
    </None>
  </ItemGroup>
</Project>

host.json

{
    "version": "2.0",
    "logging": {
        "logLevel": {
            "default": "Trace"
        }
    }
}

local.settings.json

{
    "IsEncrypted": false,
    "Values": {
        "AzureWebJobsStorage": "UseDevelopmentStorage=true",
        "FUNCTIONS_WORKER_RUNTIME": "dotnet"
    },
    "Host": {
        "LocalHttpPort": 7050
    }
}

startup.cs

using mock_backend;
using Microsoft.Azure.Functions.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using System.IO;
using System.Collections.Generic;
using Microsoft.AspNetCore.Mvc;

[assembly: FunctionsStartup(typeof(Startup))]
namespace mock_backend
{
    public class Startup : FunctionsStartup
    {
        public override void ConfigureAppConfiguration(IFunctionsConfigurationBuilder builder)
        {
            base.ConfigureAppConfiguration(builder);       <--- breakpoint not hit
        }

        public override void Configure(IFunctionsHostBuilder builder)
        {
            // Load responses for GetUpdates
            var loggerFactory = new LoggerFactory();       <--- breakpoint not hit
        }
    }
}

logs

[2021-06-03T15:21:30.835Z] Found D:\Dev\Git_Merc\testing-perf-middleware\mock-backend\mock-backend.csproj. Using for user secrets file configuration.
[2021-06-03T15:21:31.073Z] Starting Rpc Initialization Service.
[2021-06-03T15:21:31.075Z] Initializing RpcServer
[2021-06-03T15:21:31.091Z] RpcServer initialized
[2021-06-03T15:21:31.093Z] Rpc Initialization Service started.
[2021-06-03T15:21:31.097Z] Startup operation 'b9141761-313c-49ec-8dc3-84988b95e356' with parent id '(null)' created.
[2021-06-03T15:21:31.101Z] Startup operation 'b9141761-313c-49ec-8dc3-84988b95e356' starting.
[2021-06-03T15:21:31.104Z] Building host: startup suppressed: 'False', configuration suppressed: 'False', startup operation id: 'b9141761-313c-49ec-8dc3-84988b95e356'
[2021-06-03T15:21:31.118Z] Host configuration applied.
[2021-06-03T15:21:31.121Z] Reading host configuration file 'D:\Dev\Git_Merc\testing-perf-middleware\mock-backend\bin\Debug\netcoreapp3.1\host.json'
[2021-06-03T15:21:31.122Z] Host configuration file read:
[2021-06-03T15:21:31.123Z] {
[2021-06-03T15:21:31.124Z]   "version": "2.0",
[2021-06-03T15:21:31.125Z]   "logging": {
[2021-06-03T15:21:31.126Z]     "logLevel": {
[2021-06-03T15:21:31.126Z]       "default": "Trace"
[2021-06-03T15:21:31.127Z]     }
[2021-06-03T15:21:31.128Z]   }
[2021-06-03T15:21:31.129Z] }
[2021-06-03T15:21:31.135Z] Loading functions metadata
[2021-06-03T15:21:31.137Z] Reading functions metadata
[2021-06-03T15:21:31.145Z] 6 functions found
[2021-06-03T15:21:31.155Z] 6 functions loaded
[2021-06-03T15:21:31.158Z] Loading extensions from D:\Dev\Git_Merc\testing-perf-middleware\mock-backend\bin\Debug\netcoreapp3.1\bin. BundleConfigured: False, PrecompiledFunctionApp: False, LegacyBundle: False
[2021-06-03T15:21:31.163Z] Loading startup extension 'Startup'
[2021-06-03T15:21:31.186Z] Loaded extension 'Startup' (1.0.0.0)
[2021-06-03T15:21:31.197Z] IConfigurationSources registered by external startup type mock_backend.Startup:
[2021-06-03T15:21:31.199Z] Host configuration applied.
[2021-06-03T15:21:31.200Z] Reading host configuration file 'D:\Dev\Git_Merc\testing-perf-middleware\mock-backend\bin\Debug\netcoreapp3.1\host.json'
[2021-06-03T15:21:31.201Z] Host configuration file read:
[2021-06-03T15:21:31.202Z] {
[2021-06-03T15:21:31.203Z]   "version": "2.0",
[2021-06-03T15:21:31.204Z]   "logging": {
[2021-06-03T15:21:31.205Z]     "logLevel": {
[2021-06-03T15:21:31.206Z]       "default": "Trace"
[2021-06-03T15:21:31.207Z]     }
[2021-06-03T15:21:31.208Z]   }
[2021-06-03T15:21:31.209Z] }
[2021-06-03T15:21:31.219Z] Services registered by external startup type mock_backend.Startup:
[2021-06-03T15:21:31.315Z] Active host changing from '(null)' to 'f3fa0d17-f49f-4fea-945e-d38471fd263c'.
[2021-06-03T15:21:31.477Z] Initializing Warmup Extension.
[2021-06-03T15:21:31.509Z] Initializing Host. OperationId: 'b9141761-313c-49ec-8dc3-84988b95e356'.
[2021-06-03T15:21:31.517Z] Host initialization: ConsecutiveErrors=0, StartupCount=1, OperationId=b9141761-313c-49ec-8dc3-84988b95e356
[2021-06-03T15:21:31.521Z] Startup operation 'b9141761-313c-49ec-8dc3-84988b95e356' is starting host instance 'f3fa0d17-f49f-4fea-945e-d38471fd263c'.
[2021-06-03T15:21:31.523Z] Hosting starting
[2021-06-03T15:21:31.535Z] LoggerFilterOptions
[2021-06-03T15:21:31.537Z] {
[2021-06-03T15:21:31.539Z]   "MinLevel": "None",
[2021-06-03T15:21:31.540Z]   "Rules": [
[2021-06-03T15:21:31.541Z]     {
[2021-06-03T15:21:31.541Z]       "ProviderName": null,
[2021-06-03T15:21:31.542Z]       "CategoryName": null,
[2021-06-03T15:21:31.543Z]       "LogLevel": null,
[2021-06-03T15:21:31.544Z]       "Filter": "<AddFilter>b__0"
[2021-06-03T15:21:31.545Z]     },
[2021-06-03T15:21:31.546Z]     {
[2021-06-03T15:21:31.547Z]       "ProviderName": null,
[2021-06-03T15:21:31.548Z]       "CategoryName": null,
[2021-06-03T15:21:31.549Z]       "LogLevel": "Trace",
[2021-06-03T15:21:31.550Z]       "Filter": null
[2021-06-03T15:21:31.551Z]     },
[2021-06-03T15:21:31.551Z]     {
[2021-06-03T15:21:31.552Z]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[2021-06-03T15:21:31.554Z]       "CategoryName": null,
[2021-06-03T15:21:31.554Z]       "LogLevel": "None",
[2021-06-03T15:21:31.555Z]       "Filter": null
[2021-06-03T15:21:31.556Z]     },
[2021-06-03T15:21:31.557Z]     {
[2021-06-03T15:21:31.557Z]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[2021-06-03T15:21:31.558Z]       "CategoryName": null,
[2021-06-03T15:21:31.559Z]       "LogLevel": null,
[2021-06-03T15:21:31.560Z]       "Filter": "<AddFilter>b__0"
[2021-06-03T15:21:31.561Z]     },
[2021-06-03T15:21:31.562Z]     {
[2021-06-03T15:21:31.562Z]       "ProviderName": "Azure.Functions.Cli.Diagnostics.ColoredConsoleLoggerProvider",
[2021-06-03T15:21:31.563Z]       "CategoryName": null,
[2021-06-03T15:21:31.564Z]       "LogLevel": null,
[2021-06-03T15:21:31.565Z]       "Filter": "<AddFilter>b__0"
[2021-06-03T15:21:31.566Z]     }
[2021-06-03T15:21:31.567Z]   ]
[2021-06-03T15:21:31.568Z] }
[2021-06-03T15:21:31.569Z] LoggerFilterOptions
[2021-06-03T15:21:31.570Z] {
[2021-06-03T15:21:31.571Z]   "MinLevel": "None",
[2021-06-03T15:21:31.572Z]   "Rules": [
[2021-06-03T15:21:31.572Z]     {
[2021-06-03T15:21:31.573Z]       "ProviderName": null,
[2021-06-03T15:21:31.574Z]       "CategoryName": null,
[2021-06-03T15:21:31.574Z]       "LogLevel": null,
[2021-06-03T15:21:31.575Z]       "Filter": "<AddFilter>b__0"
[2021-06-03T15:21:31.576Z]     },
[2021-06-03T15:21:31.577Z]     {
[2021-06-03T15:21:31.578Z]       "ProviderName": null,
[2021-06-03T15:21:31.579Z]       "CategoryName": null,
[2021-06-03T15:21:31.580Z]       "LogLevel": "Trace",
[2021-06-03T15:21:31.581Z]       "Filter": null
[2021-06-03T15:21:31.581Z]     },
[2021-06-03T15:21:31.583Z]     {
[2021-06-03T15:21:31.583Z]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[2021-06-03T15:21:31.584Z]       "CategoryName": null,
[2021-06-03T15:21:31.585Z]       "LogLevel": "None",
[2021-06-03T15:21:31.586Z]       "Filter": null
[2021-06-03T15:21:31.587Z]     },
[2021-06-03T15:21:31.588Z]     {
[2021-06-03T15:21:31.589Z]       "ProviderName": "Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics.SystemLoggerProvider",
[2021-06-03T15:21:31.590Z]       "CategoryName": null,
[2021-06-03T15:21:31.591Z]       "LogLevel": null,
[2021-06-03T15:21:31.591Z]       "Filter": "<AddFilter>b__0"
[2021-06-03T15:21:31.592Z]     },
[2021-06-03T15:21:31.593Z]     {
[2021-06-03T15:21:31.594Z]       "ProviderName": "Azure.Functions.Cli.Diagnostics.ColoredConsoleLoggerProvider",
[2021-06-03T15:21:31.595Z]       "CategoryName": null,
[2021-06-03T15:21:31.595Z]       "LogLevel": null,
[2021-06-03T15:21:31.596Z]       "Filter": "<AddFilter>b__0"
[2021-06-03T15:21:31.597Z]     }
[2021-06-03T15:21:31.598Z]   ]
[2021-06-03T15:21:31.598Z] }
[2021-06-03T15:21:31.599Z] FunctionResultAggregatorOptions
[2021-06-03T15:21:31.600Z] {
[2021-06-03T15:21:31.600Z]   "BatchSize": 1000,
[2021-06-03T15:21:31.601Z]   "FlushTimeout": "00:00:30",
[2021-06-03T15:21:31.602Z]   "IsEnabled": true
[2021-06-03T15:21:31.603Z] }
[2021-06-03T15:21:31.604Z] SingletonOptions
[2021-06-03T15:21:31.604Z] {
[2021-06-03T15:21:31.605Z]   "LockPeriod": "00:00:15",
[2021-06-03T15:21:31.606Z]   "ListenerLockPeriod": "00:00:15",
[2021-06-03T15:21:31.606Z]   "LockAcquisitionTimeout": "10675199.02:48:05.4775807",
[2021-06-03T15:21:31.607Z]   "LockAcquisitionPollingInterval": "00:00:05",
[2021-06-03T15:21:31.608Z]   "ListenerLockRecoveryPollingInterval": "00:01:00"
[2021-06-03T15:21:31.608Z] }
[2021-06-03T15:21:31.610Z] Starting JobHost
[2021-06-03T15:21:31.613Z] Starting Host (HostId=desktop-1919806725, InstanceId=f3fa0d17-f49f-4fea-945e-d38471fd263c, Version=3.0.15828.0, ProcessId=16204, AppDomainId=1, InDebugMode=True, InDiagnosticMode=False, FunctionsExtensionVersion=(null))
[2021-06-03T15:21:31.624Z] Loading functions metadata
[2021-06-03T15:21:31.639Z] 6 functions loaded
[2021-06-03T15:21:31.646Z] Adding Function descriptor provider for language dotnet.
[2021-06-03T15:21:31.647Z] Creating function descriptors.
[2021-06-03T15:21:31.674Z] Function descriptors created.
[2021-06-03T15:21:31.676Z] Generating 6 job function(s)
[2021-06-03T15:21:31.697Z] Found the following functions:
[2021-06-03T15:21:31.698Z] mock_backend.getCustomScripts.Run
[2021-06-03T15:21:31.699Z] mock_backend.getUpdates.Run
[2021-06-03T15:21:31.700Z] mock_backend.jSprintSecurityCheck.Run
[2021-06-03T15:21:31.701Z] mock_backend.login.Run
[2021-06-03T15:21:31.702Z] mock_backend.getAgentMetrics.Run
[2021-06-03T15:21:31.703Z] mock_backend.setAvailability.Run
[2021-06-03T15:21:31.704Z] 
[2021-06-03T15:21:31.707Z] HttpOptions
[2021-06-03T15:21:31.708Z] {
[2021-06-03T15:21:31.707Z] Initializing function HTTP routes
[2021-06-03T15:21:31.709Z]   "DynamicThrottlesEnabled": false,
[2021-06-03T15:21:31.712Z]   "EnableChunkedRequestBinding": false,
[2021-06-03T15:21:31.713Z]   "MaxConcurrentRequests": -1,
[2021-06-03T15:21:31.711Z] Mapped function route 'api/customScript' [get] to 'getCustomScripts'
[2021-06-03T15:21:31.714Z]   "MaxOutstandingRequests": -1,
[2021-06-03T15:21:31.715Z] Mapped function route 'api/messages' [get] to 'getUpdates'
[2021-06-03T15:21:31.715Z]   "RoutePrefix": "api"
[2021-06-03T15:21:31.716Z] Mapped function route 'api/j_spring_security_check' [post] to 'jSpringSecurityCheck'
[2021-06-03T15:21:31.717Z] }
[2021-06-03T15:21:31.717Z] Mapped function route 'api/login' [post] to 'login'
[2021-06-03T15:21:31.719Z] Mapped function route 'api/metric/realtime' [get] to 'metrics'
[2021-06-03T15:21:31.719Z] Mapped function route 'api/agentStatus' [post] to 'setAvailability'
[2021-06-03T15:21:31.720Z] 
[2021-06-03T15:21:31.727Z] Host initialized (106ms)
[2021-06-03T15:21:31.729Z] Host started (114ms)
[2021-06-03T15:21:31.730Z] Job host started
[2021-06-03T15:21:31.750Z] File event source initialized.
[2021-06-03T15:21:31.754Z] Debug file watch initialized.
[2021-06-03T15:21:31.755Z] Diagnostic file watch initialized.
[2021-06-03T15:21:31.757Z] Hosting started
[2021-06-03T15:21:31.758Z] Startup operation 'b9141761-313c-49ec-8dc3-84988b95e356' completed.

Functions:

        getCustomScripts: [GET] http://localhost:7050/api/customScript

        getUpdates: [GET] http://localhost:7050/api/messages

        jSpringSecurityCheck: [POST] http://localhost:7050/api/j_spring_security_check

        login: [POST] http://localhost:7050/api/login

        metrics: [GET] http://localhost:7050/api/metric/realtime

        setAvailability: [POST] http://localhost:7050/api/agentStatus

For detailed output, run func with --verbose flag.
[2021-06-03T15:21:32.196Z] Executing HTTP request: {
[2021-06-03T15:21:32.198Z]   requestId: "358761a7-b43c-4101-83d8-00648f139578",
[2021-06-03T15:21:32.199Z]   method: "GET",
[2021-06-03T15:21:32.201Z]   userAgent: "ms-rest-js/2.3.0 Node/v14.16.0 OS/(x64-Windows_NT-10.0.19042) vscode-azurefunctions/1.4.0",
[2021-06-03T15:21:32.202Z]   uri: "/admin/host/status"
[2021-06-03T15:21:32.203Z] }
[2021-06-03T15:21:32.331Z] Host Status: {
[2021-06-03T15:21:32.333Z]   "id": "desktop-1919806725",
[2021-06-03T15:21:32.334Z]   "state": "Running",
[2021-06-03T15:21:32.335Z]   "version": "3.0.15828.0",
[2021-06-03T15:21:32.336Z]   "versionDetails": "3.0.15828 Commit hash: 70fa587c9dcd1f126abebc6432c4d8c7b2e32155",
[2021-06-03T15:21:32.337Z]   "platformVersion": "",
[2021-06-03T15:21:32.338Z]   "instanceId": "",
[2021-06-03T15:21:32.339Z]   "computerName": "DESKTOP",
[2021-06-03T15:21:32.339Z]   "processUptime": 14401962
[2021-06-03T15:21:32.340Z] }
[2021-06-03T15:21:32.354Z] Executed HTTP request: {
[2021-06-03T15:21:32.355Z]   requestId: "358761a7-b43c-4101-83d8-00648f139578",
[2021-06-03T15:21:32.358Z]   identities: "(WebJobsAuthLevel:Admin, WebJobsAuthLevel:Admin)",
[2021-06-03T15:21:32.359Z]   status: "200",
[2021-06-03T15:21:32.360Z]   duration: "155"
[2021-06-03T15:21:32.361Z] }
[2021-06-03T15:21:36.680Z] FUNCTIONS_WORKER_RUNTIME=dotnet. Will shutdown all the worker channels that started in placeholder mode
[2021-06-03T15:21:36.842Z] Host lock lease acquired by instance ID '0000000000000000000000003286B7DC'.
[2021-06-03T15:21:37.309Z] Executing HTTP request: {
[2021-06-03T15:21:37.310Z]   requestId: "3bc6794f-3428-4ff3-8f03-a6e8ad244288",
[2021-06-03T15:21:37.311Z]   method: "GET",
[2021-06-03T15:21:37.312Z]   userAgent: "PostmanRuntime/7.28.0",
[2021-06-03T15:21:37.313Z]   uri: "/api/messages"
[2021-06-03T15:21:37.314Z] }
[2021-06-03T15:21:37.319Z] Request successfully matched the route with name 'getUpdates' and template 'api/messages'
[2021-06-03T15:21:37.344Z] Executing 'getUpdates' (Reason='This function was programmatically called via the host APIs.', Id=cec4598b-ab9c-46c3-806d-17ded7078425)
[2021-06-03T15:21:37.358Z] Executed 'getUpdates' (Succeeded, Id=cec4598b-ab9c-46c3-806d-17ded7078425, Duration=25ms)
[2021-06-03T15:21:37.363Z] Executing HttpStatusCodeResult, setting HTTP status code 204
[2021-06-03T15:21:37.365Z] Executed HTTP request: {
[2021-06-03T15:21:37.366Z]   requestId: "3bc6794f-3428-4ff3-8f03-a6e8ad244288",
[2021-06-03T15:21:37.367Z]   identities: "(WebJobsAuthLevel:Admin)",
[2021-06-03T15:21:37.367Z]   status: "204",
[2021-06-03T15:21:37.369Z]   duration: "55"
[2021-06-03T15:21:37.370Z] }
@ghost ghost assigned madelinegordon Jun 3, 2021
@zhenyuan0502
Copy link

You might try to reproduce by new fresh project to test it. As I see, you should hit the breakpoint from the configuration you posted. My project using Visual Studio hit perfectly, all config are the same with you.

@mmulhearn
Copy link
Author

I was able to replicate this with a barebones new repo: https://github.com/mmulhearn/azure-func-startup-issue

@zhenyuan0502
Copy link

@mmulhearn Seem it's an known bug on Visual Code on this repository has raised: microsoft/vscode-azurefunctions#1971

Actually it will run, but, it can't hit a breakpoint

But if you take debugging in Visual Studio, it worked fine.

image

@v-bbalaiagar v-bbalaiagar self-assigned this Jun 7, 2021
@mmulhearn
Copy link
Author

@zhenyuan0502 thank you. Didn't even cross my mind that the IDE isn't attaching fast enough. Thank you for linking.

@v-bbalaiagar
Copy link

Hi @mmulhearn, Let us know if the above information resolves your query, or if you have any further queries.

@mmulhearn
Copy link
Author

Yes, I can follow the linked issue as that seems to be the problem. Launching from VS works. Thanks @zhenyuan0502

@ghost ghost locked as resolved and limited conversation to collaborators Jul 8, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@mmulhearn @zhenyuan0502 @madelinegordon @v-bbalaiagar