Duplicate logs

[brettsam]

I've seen several people report that they're seeing duplicate logs:

• Queued Item marked invisible after idle time/redeploy of code. #1605 (comment)
• https://stackoverflow.com/questions/44715288/azure-function-firing-twice-vs-2017-preview
• One internal customer

[brettsam]

@rndthoughts -- when you say you were viewing "Streaming logs" and saw duplicates, did you mean this view (1):

or this view (2)?:

Also, what file did you download via FTP where you said you saw duplicate logs?

[rndthoughts]

I was looking at view (2) - the portal streaming logs view. The file via FTP was located in LogFiles\Application\Functions\Function\ClientApiUpdates.

[brettsam]

@ahmelsayed -- Is this a known issue? It looks like several people are seeing dupe logs in the Streaming logs view.

[ahmelsayed]

that would be expected for the (2) view above. The runtime double logs stuff into the function specific logs (under LogFiles\Application\Functions\Function\<functionName>) then again in the host logs (under LogFiles\Application\Functions\host), the (2) view is a rollup of all activity under LogFiles\Application\ while the view you get in the functions portal itself is scoped to changes in LogFiles\Application\Functions\Function\<functionName>

[ahmelsayed]

The reports are a bit unclear to me. I can't tell where exactly are people seeing these duplicate logs. As I mentioned they are expected for view (2) above, but not view (1) and not in the CLI. are any reports saying that about (1) or the cli?

[DivineOps]

I am not sure this is the same issue, but it's similar enough.
What I am seeing is duplicate logs in local debugging environment only, for exceptions (both handled and unhandled) only. The function invocation is logged once, but the exception is logged more than once.
Have seen this through multiple versions of functions local tools

[paulbatum]

I just reproduced on 1.0.0-beta.100, here's the output from a single failed queue trigger execution:

7/5/2017 6:49:14 PM] Function started (Id=9ecbee53-a558-4cae-9606-82d93b42d0f8)
[7/5/2017 6:49:16 PM] Function completed (Failure, Id=9ecbee53-a558-4cae-9606-82d93b42d0f8, Duration=1947ms)
[7/5/2017 6:49:16 PM]
[7/5/2017 6:49:16 PM] A ScriptHost error has occurred
[7/5/2017 6:49:16 PM] Exception while executing function: Functions.QueueTriggerCSharp. mscorlib: Exception has been thrown by the target of an invocation. FunctionApp3: failing.
[7/5/2017 6:49:16 PM] Exception while executing function: Functions.QueueTriggerCSharp. mscorlib: Exception has been thrown by the target of an invocation. FunctionApp3: failing.
[7/5/2017 6:49:16 PM]
[7/5/2017 6:49:16 PM] Exception while executing function: Functions.QueueTriggerCSharp
[7/5/2017 6:49:16 PM] Exception while executing function: Functions.QueueTriggerCSharp. mscorlib: Exception has been thrown by the target of an invocation. FunctionApp3: failing.
[7/5/2017 6:49:16 PM] Executed 'Functions.QueueTriggerCSharp' (Failed, Id=9ecbee53-a558-4cae-9606-82d93b42d0f8)
[7/5/2017 6:49:16 PM] mscorlib: Exception while executing function: Functions.QueueTriggerCSharp. mscorlib: Exception has been thrown by the target of an invocation. FunctionApp3: failing.
[7/5/2017 6:49:16 PM]   Function had errors. See Azure WebJobs SDK dashboard for details. Instance ID is '9ecbee53-a558-4cae-9606-82d93b42d0f8'
[7/5/2017 6:49:16 PM] mscorlib: Exception while executing function: Functions.QueueTriggerCSharp. mscorlib: Exception has been thrown by the target of an invocation. FunctionApp3: failing.

[justcla]

I am experiencing this in Visual Studio 15.5 when viewing the Streaming Logs.

The logs of a basic function generate duplicate messages.

Connecting to Application logs ...
2018-01-22T07:51:02  Welcome, you are now connected to log-streaming service.
Application: 2018-01-22T07:52:02  No new trace in the past 1 min(s).
Application: 2018-01-22T07:53:02  No new trace in the past 2 min(s).
Application: 2018-01-22T07:54:00.485 Host Status: {
Application:   "id": "functionapp20180121110616",
Application:   "state": "Running",
Application:   "version": "1.0.11469.0"
Application: }
Application: 2018-01-22T07:54:02.158 Host Status: {
Application:   "id": "functionapp20180121110616",
Application:   "state": "Running",
Application:   "version": "1.0.11469.0"
Application: }
Application: 2018-01-22T07:54:14.196 Function started (Id=f6b13eda-07e0-4f0b-ba0b-0bd93086071c)
Application: 2018-01-22T07:54:14.196 C# Queue trigger function processed: Test message 6
Application: 2018-01-22T07:54:14.196 Function completed (Success, Id=f6b13eda-07e0-4f0b-ba0b-0bd93086071c, Duration=2ms)
Application: 2018-01-22T07:54:14.196 Function started (Id=f6b13eda-07e0-4f0b-ba0b-0bd93086071c)
Application: 2018-01-22T07:54:14.196 Executing 'Function1' (Reason='New queue message detected on 'test-items'.', Id=f6b13eda-07e0-4f0b-ba0b-0bd93086071c)
Application: 2018-01-22T07:54:14.196 C# Queue trigger function processed: Test message 6
Application: 2018-01-22T07:54:14.196 Function completed (Success, Id=f6b13eda-07e0-4f0b-ba0b-0bd93086071c, Duration=2ms)
Application: 2018-01-22T07:54:14.211 Executed 'Function1' (Succeeded, Id=f6b13eda-07e0-4f0b-ba0b-0bd93086071c)

Repro:

• Create a basic Queue Function Project and publish it to Azure.
• Open Cloud Explorer and view streaming logs
• Ensure there is a queue named “myqueue-items” in the storage account configured for the function.
• Add a message to the queue.
• Watch the logs.
• Debugging message are printed twice.

If this is because the Streaming Log viewer is collating messages from various sources (as mentioned above), perhaps we could introduce a filter so I can choose which logs to see.
Another option might be to prepend the log file location to the output line so we can see which logs are reporting which messages.

[auslavs]

I saw this issue after renaming the functions class e.g. "public static class BlobTrigger"
"public static class MeaningFullName_BlobTrigger"

[FlavioDiasPs]

Well, I am facing the same issue at vscode when streaming the whole Function App.
When streaming the function individually, it doesn't duplicate.

Any progress on that?

[TobiasBengtsson]

I am facing the same issue when checking the logs in Application Insights.

I know that 901 actual requests were sent to the Function HTTP endpoint.

The Kusto query in Application Insights traces | where operation_Name == "MyHttpTriggerFunction" | where message startswith "Executing" | count returns 911 responses. I've tracked down 10 duplicates that have the exact same timestamp, Id and operation_Id.

Even worse, under Home > App Services > MyFunction - MyHttpTriggerFunction, under the "Monitor" tab, I see 961 executions.

I'm worried that we'll have to pay for the higher amount of shown executions which would be a 7% extra cost compared to reality.

(The names of the app and function are fictitious)

[paulbatum]

To figure out exactly what you're charged for, see:
https://github.com/Azure/Azure-Functions/wiki/Consumption-Plan-Cost-Billing-FAQ#how-can-i-view-graphs-of-execution-count-and-gb-seconds

[brettsam]

@TobiasBengtsson -- since this issue about the streaming logs, I've created a new issue to track this and figure out what's going on: #4268

[amamounelsayed]

@brettsam: For view 2, the log stream from the app level portal is using the url https:/.scm.azurewebsites.net/api/logstream.

As we have some logs the same in the host file and the function they both will propagate.
The question do we need the messages to be logged in both files. Referring to #1627 (comment)

Thank you!

[rcarmo]

This is still a thing, I see. Any chance of a fix? I have some debugging log entries that are quite verbose, and scrolling through them is a major pain.

[weng271190436]

I am also seeing this. Every single custom log is logged twice:

[ClaytonBrawley]

Still seeing this issue. Any updates on this?

[ThisDevDane]

We're also having this problem at work it's a problem since other services we have that use logs for processing also get's the double because of this.

[brettsam]

@weng271190436 (and everyone for that matter) -- are you doing anything custom with your logging (like using FunctionsStartup to register additional logging?). The fact that it's only your logs being written twice is interesting.

Including the host version (v1, 2, 3) is helpful -- as well as a screenshot of where you're seeing these dupes, and what the log messages are.

[arkiaconsulting]

@ClaytonBrawley I had the same issue, and @brettsam is right, i used AddApplicationInsightsWebjobs from the FunctionsStartup. Once I removed this extension method, the traces were logged once (as soon as the APPINSIGHTS_INSTRUMENTATIONKEY setting is set).

[pcgeek86]

I'm also seeing duplicated logs in the Visual Studio Code extension, when streaming logs are connected.

[ckarcz]

when using Serilog with a sink to AI, we also get duplicate logs.

serilog-contrib/serilog-sinks-applicationinsights#157

there is no way to remove the default LoggerProviders as the Azure function runtime validates these are required services in order to start up. can validation of loggers be removed?