Function execution logs are duplicated in App Service log stream

[paulbatum]

If you access the log stream for your entire function app, you will see duplicated entries for function starting/completion:

When a function executes with file logging enabled, the following entries are written to both the host log and the function log, i.e. to files in:

• D:\home\LogFiles\Application\Functions\Host\

• D:\home\LogFiles\Application\Functions\Function\function-name\

The entries look like this:

2017-04-18T22:54:20.013 Function started (Id=8c130624-cfb2-47d7-8e1f-05047a10a17d)
2017-04-18T22:54:20.013 Function completed (Success, Id=8c130624-cfb2-47d7-8e1f-05047a10a17d, Duration=0ms)

Because the same entry is written to both locations, it appears in the log stream twice.

[fmannhardt]

This is highly confusing and just cost me a few hours of searching for the reason. It should be fixed or one need to somehow be warned.

[jwisener]

This is an issue that cost a considerable amount of time. Since this issue has been open for 3 years are there any plans to address this?

[njabulomp]

I am experiencing an issue where the invocation of an http triggered function app from a logic app is happening twice, I checked the invocation logs and app insights and did indeed see two calls being made. The logic app is showing one call being made but the function app is being called twice. I am using version 2 (2.0.12961.0) of the functions sdk.

[ravick4u]

This issue was opened in 2017 and I am writing this in 2020... :) I am using Azure Function V3 and issue is still exists

[paulbatum]

I think there are two different things being discussed here. The behavior that @njabulomp mentioned is about a function actually running twice. That is not what this issue is about. This issue is about the fact that the streaming logs UX for an entire webapp/functionapp subscribes to all file log changes that happen within the D:\home\LogFiles folder. If the same log entry is written to two different files, then this consolidated view will show the entry twice.

Since this issue is filed against the functions host, the change that makes the most sense would be for the host level log not include any log entries that will appear in the per-function logs. However I am not sure whether that would break some existing workflows?

[paulbatum]

@brettsam @mathewc are there any host.json settings that would control what level of logs are written to the host log at D:\home\LogFiles\Application\Functions\Host? I am guessing no?

[mathewc]

No, the only file logging knob is "fileLoggingEnabled". The issue is that the Log Streaming view is rooted on the parent directory (getting both host/function logs), while the function Logs view is rooted on the individual function directory:

The log files/data are correct. I think we just need to change the Log Streaming view to root on the host log dir, which should include everything you'd want to see.

[paulbatum]

That might work. I'm asking someone from the portal team.

[paulbatum]

We think Mathew's suggested approach makes sense. I should have another update in a few weeks. While the work is happening in a different component, I'll leave this issue open for the time being.

[pcgeek86]

3+ years later ... any fix for this? I'm seeing this behavior as well.

#1627

[paulbatum]

@pcgeek86 Can you let us know if you're still having a problem with this? We recently deployed some of the changes that were discussed above.

[santo2]

I'm not sure if this is related, but I see double logging in application insights on the function logs

• Executing 'PurposePartner_Prebooking_CRUD' (Reason='(null)', Id=20562e22-a6d1-40f7-8efe-05151bf28483)

• ddb25fc2e69041788466c955c9fee617: Function 'PurposePartner_Prebooking_CRUD (Orchestrator)' started. IsReplay: False. Input: (1692 bytes). State: Started. HubName: xxx. AppName: xxx SlotName: Production. ExtensionVersion: 2.3.0. SequenceNumber: 8. TaskEventId: -1

• they have different ItemIds

• they have different customDimensions:

customdimensions of item 1

{"prop__{OriginalFormat}":"Executing '{functionName}' (Reason='{reason}', Id={invocationId})","HostInstanceId":"fe9c82c2-8735-43ab-9e48-ae88d01f5629","ProcessId":"2428","Category":"Function.PurposePartner_Prebooking_CRUD","InvocationId":"20562e22-a6d1-40f7-8efe-05151bf28483","LogLevel":"Information","prop__functionName":"PurposePartner_Prebooking_CRUD","prop__invocationId":"20562e22-a6d1-40f7-8efe-05151bf28483","EventId":"1","EventName":"FunctionStarted"}
--

Customdimensions of item 2

{"EventId":"1","EventName":"FunctionStarted","CategoryName":"Function.PurposePartner_Prebooking_CRUD","{OriginalFormat}":"Executing '{functionName}' (Reason='{reason}', Id={invocationId})","MS_FunctionInvocationId":"20562e22-a6d1-40f7-8efe-05151bf28483","MS_OperationContext":"Microsoft.ApplicationInsights.Extensibility.Implementation.OperationHolder`1[Microsoft.ApplicationInsights.DataContracts.RequestTelemetry]","MS_HostInstanceId":"00000000-0000-0000-0000-000000000000","MS_FunctionName":"PurposePartner_Prebooking_CRUD","functionName":"PurposePartner_Prebooking_CRUD","MS_Event":"FunctionStart","invocationId":"20562e22-a6d1-40f7-8efe-05151bf28483"}
--

• we have a functionsstartup, with AddLogging( AddApplicationInsights)

[brettsam]

You should not be adding ApplicationInsights yourself -- the functions host takes care of that. https://docs.microsoft.com/en-us/azure/azure-functions/functions-dotnet-dependency-injection#logging-services

[yobyot]

I sure wish the team would fix this. It doesn't happen locally so the "fidelity" is off for testing between local and Azure function.

[paulbatum]

@yobyot Can you clarify what you mean? Are you still seeing duplicate log messages in the log stream view for the full function app? We deployed a fix for this a while ago. If you can include a screenshot that would be helpful.

[nickplennox]

@paulbatum I am seeing dup log entries on Azure functions, log below from today. All I am doing is calling context.log from my node.js app:

2021-02-12T16:37:52.738 [Information] Executing 'Functions.getViewModel' (Reason='This function was programmatically called via the host APIs.',Id=1ec7165f-0f8c-4997-9e26-xxxxxxxxxxxxb83)
2021-02-12T16:37:52.743 [Information] getViewModel:
2021-02-12T16:37:52.746 [Information] validateAndReturnMultipleProviders:
2021-02-12T16:37:52.746 [Information] multi-auth: validateAndReturnGoogle:
2021-02-12T16:37:52.775 [Information] getSigningKey: Returning public key
2021-02-12T16:37:52.779 [Information] multi-auth: validateAndReturnGoogle: JWT verified successfully
2021-02-12T16:37:52.779 [Information] getOrRefreshxxTokens:
2021-02-12T16:37:52.779 [Information] getOrRefreshxxTokensAppleGoogle:
2021-02-12T16:37:52.827 [Information] getOrRefreshxxTokensAppleGoogle: Found xxxx Record for token refresh
2021-02-12T16:37:52.829 [Information] getOrRefreshxxTokensAppleGoogle: Token has expired
2021-02-12T16:37:52.829 [Information] refreshxxToken:
2021-02-12T16:37:52.738 [Information] Executing 'Functions.getViewModel' (Reason='This function was programmatically called via the host APIs.', Id=1ec7165f-0f8c-4997-9e26-xxxxxxxxxxxxb83)
2021-02-12T16:37:52.743 [Information] getViewModel:
2021-02-12T16:37:52.746 [Information] validateAndReturnMultipleProviders:
2021-02-12T16:37:52.746 [Information] multi-auth: validateAndReturnGoogle:
2021-02-12T16:37:52.775 [Information] getSigningKey: Returning public key
2021-02-12T16:37:52.779 [Information] multi-auth: validateAndReturnGoogle: JWT verified successfully
2021-02-12T16:37:52.779 [Information] getOrRefreshxxTokens:
2021-02-12T16:37:52.779 [Information] getOrRefreshxxTokensAppleGoogle:
2021-02-12T16:37:52.827 [Information] getOrRefreshxxTokensAppleGoogle: Found xxxx Record for token refresh
2021-02-12T16:37:52.829 [Information] getOrRefreshxxTokensAppleGoogle: Token has expired
.
.
.

It's taken considerable time to reassure myself that my functions are not being invoked twice every time, but note that the timestamps are identical in the repeated sections. Does that help at all?

Nick

[paulbatum]

Not really, the question I asked was what view people are seeing this in. This issue is specifically about the behavior of the full streaming logs view in the azure portal when scoped to the application level. If you are seeing duplicate logs in a different context, for example if there are duplicates in appinsights, then its a different problem and you should file a new issue.

[nickplennox]

OK, the log above is the output of az webapp log tail ... apols if that's off topic. The logs in the Azure portal don't show these duplicates.

[paulbatum]

Huh ok, I suspect az webapp log tail has the same issue that this view in the portal did, i.e. its not using the right directory for functions.

I filed: Azure/azure-cli#16921

[nickplennox]

Thanks Paul

[paulbatum]

Also I found a workaround - add --provider application/functions/host

[nickplennox]

Ah, I see what you did there. Neat!

Thank you :)

[JohnCarmichael3000]

Any update on this? I was seeing double logging in "az webapp log tail" output for a function this week.

[idusortus]

Five years later and this is still a nuisance. Any solution in sight?

[mofriedkj]

i have the same issue that the http trigger func get executed twice,that cause me a lot of problems

[MatheusNani]

I have a similar issue with a Timer Trigger Function.
For some reason it's being kickoff twice in a row and I'm getting duplicate emails.
Any updates regarding this issue?

[idusortus]

@MatheusNani That's a duplicate execution, not an unexpected duplicate log entry. You may have better luck asking on stackoverflow.

[stmax82]

Duplicate (and out of order) logs when using curl for log streaming... same happens in the browser. This totally kills log streaming...