search

Azure / azure-functions-host

The host/runtime that powers Azure Functions
https://functions.azure.com
MIT License
1.93k stars 441 forks source link

Duplicate logs #1627

Open brettsam opened 7 years ago

brettsam commented 7 years ago

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

brettsam commented 7 years ago

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

or this view (2)?: image

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

rndthoughts commented 7 years ago

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

brettsam commented 7 years ago

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

ahmelsayed commented 7 years ago

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 commented 7 years ago

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 commented 7 years ago

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

image

paulbatum commented 7 years ago

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 commented 6 years ago

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:

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 commented 5 years ago

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

FlavioDiasPs commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

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 commented 5 years ago

@TobiasBengtsson -- since this issue about the streaming logs, I've created a new issue to track this and figure out what's going on: https://github.com/Azure/azure-functions-host/issues/4268

amamounelsayed commented 5 years ago

@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 https://github.com/Azure/azure-functions-host/issues/1627#issuecomment-312045092

Thank you!

rcarmo commented 5 years ago

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 commented 4 years ago

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

ClaytonBrawley commented 4 years ago

Still seeing this issue. Any updates on this?

ThisDevDane commented 4 years ago

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 commented 4 years ago

@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 commented 4 years ago

@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 commented 4 years ago

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

image

ckarcz commented 2 years ago

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

https://github.com/serilog-contrib/serilog-sinks-applicationinsights/issues/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?