Distributed Tracing enabled - logs are duplicated

[tonto7973]

When Distributed Tracing is enabled, some logs (warnings and errors) are duplicated in Application Insights.

Investigative information

• Timestamp: 14th July 2020 9:51 UTC
• Invocation ID: 1d98377b-bd28-44be-870d-d1705c6e2b5a
• Function Region: East US
• App Insights Region: UK South

Repro steps

Run the following function:

@FunctionName("HttpTrigger-Java")
public HttpResponseMessage run(
            @HttpTrigger(name = "req", methods = {HttpMethod.GET, HttpMethod.POST}, authLevel = AuthorizationLevel.ANONYMOUS)
            HttpRequestMessage<Optional<String>> request,
            final ExecutionContext context) {

        context.getLogger().log(Level.INFO, "I: This is an info");
        context.getLogger().log(Level.WARNING, "W: This is a warning {0}", "arg1");
        context.getLogger().log(Level.SEVERE, "S: This is an error {0}", 123);

        return request.createResponseBuilder(HttpStatus.OK).body("Done").build();
}

Observe Application Insights some minutes later. The traces reported as WARNING or SEVERE are duplicated (INFO is not duplicated):

timestamp,message,severityLevel,itemType,customDimensions,"operation_Name","operation_Id","operation_ParentId","cloud_RoleInstance",sdkVersion
"2020-07-14T09:51:08.954Z","W: This is a warning arg1",2,trace,"{""LoggingLevel"":""WARNING"",""SourceType"":""Logger"",""TimeStamp"":""Tue, 14 Jul 2020 09:51:08 GMT""}",,9cc3d2a0875a744d81c3be6152796d92,7ae9bdd9609e734d,RD00155D6643DA,"awr_java:2.5.1"
"2020-07-14T09:51:09.092Z","S: This is an error 123",3,trace,"{""LoggingLevel"":""SEVERE"",""SourceType"":""Logger"",""TimeStamp"":""Tue, 14 Jul 2020 09:51:09 GMT""}",,9cc3d2a0875a744d81c3be6152796d92,7ae9bdd9609e734d,RD00155D6643DA,"awr_java:2.5.1"
"2020-07-14T09:51:09.2132066Z","W: This is a warning {0}",2,trace,"{""HostInstanceId"":""92525f25-d8d3-4bf4-abba-97b833203912"",""InvocationId"":""1d98377b-bd28-44be-870d-d1705c6e2b5a"",""ProcessId"":""7720"",""Category"":""Function.HttpTrigger-Java.User"",""LogLevel"":""Warning""}","HttpTrigger-Java",9cc3d2a0875a744d81c3be6152796d92,7ae9bdd9609e734d,e8228ec522d0bb0cde1261622aaf3fb9855105fb7485023fe847aa1a3a4e8100,"azurefunctions: 3.0.13901.0"
"2020-07-14T09:51:09.2193274Z","S: This is an error {0}",3,trace,"{""HostInstanceId"":""92525f25-d8d3-4bf4-abba-97b833203912"",""InvocationId"":""1d98377b-bd28-44be-870d-d1705c6e2b5a"",""ProcessId"":""7720"",""Category"":""Function.HttpTrigger-Java.User"",""LogLevel"":""Error""}","HttpTrigger-Java",9cc3d2a0875a744d81c3be6152796d92,7ae9bdd9609e734d,e8228ec522d0bb0cde1261622aaf3fb9855105fb7485023fe847aa1a3a4e8100,"azurefunctions: 3.0.13901.0"

• Some logs do not contain invocationId, and some do.
• Additionally, the log entries that do contain invocationId are not formatted correctly.

Expected behavior

1. Logs are not duplicated
2. Logs are formatted correctly
3. Invocation id is present in logs

Actual behavior

• Logs are duplicated
• Some logs do not contain invocationId
• Some logs are not formatted correctly

Known workarounds

• Disabling distributed tracing solves the duplication, but doesn't solve formatting issues.

[amamounelsayed]

Thank you so much for your message, Expected behavior Logs are not duplicated -> correct as a work around please can you use java.util logs instead of context.getLogger Logs are formatted correctly - what is the format that you are expecting? Invocation id is present in logs - Why do you need the invocation Id?

Thank you so much.

cc @trask

[tonto7973]

Hi @amamounelsayed ,

Note - AAI acronym below stands for Azure Application Insights.

1. Logs are not duplicated -> correct as a work around please can you use java.util logs instead of context.getLogger

Yes, I can, but doing this I loose additional information from customDimensions (HostInstanceId, InvocationId, ProcessId) which I need for diagnostics and troubleshooting. I can potentially add InstanceId by registering a custom root logging handler, but I cannot capture the other custom dimensions.

2. Logs are formatted correctly - what is the format that you are expecting?

When calling context.getLogger().log(Level.WARNING, "W: This is a warning {0}", "arg1"); this is what I mean:

Expected message in AAI: "W: This is a warning arg1"
Actual message in AAI:   "W: This is a warning {0}"

As a workaround I register a custom filter with the context logger to format the message, but this has to be done with every single invocation. This could be done at the worker level instead. Other workaround is to use java.util logs that format the message correctly, but we loose additional information as described above.

3. Invocation id is present in logs

This is not true when using java.util logs. It is present only when using context.getLogger().log. I need the invocationid for diagnostics and troubleshooting.

---

I think the reason for this behaviour is that logs from context.getLogger() are passed via RPC to underlying function host that attaches the additional information, such as HostInstanceId, InvocationId, ProcessId, to the telemetry. In comparison, java.util logs are captured by AAI java agent that doesnt' know about any of the aforementioned custom dimensions.

The main issue is that context.getLogger() logs get duplicated in AAI only when Level.WARNING or higher is used, presumably because the functions host outputs these to Console.Error and not Console.Out. For whatever the reason, java agent picks those logs and adds them to AAI, polluting the traces with duplicated information.

---

Current workaround inside my function - it has to be applied before any log statements:

context.getLogger().setFilter(record -> {
    // fix formatting
    final Object[] parameters = record.getParameters();
    if (parameters != null && parameters.length > 0) {
        final String formattedMessage = new SimpleFormatter().formatMessage(record);
        record.setMessage(formattedMessage);
        record.setParameters(null);
    }
    
    // prevent duplicates by overriding the logger level
    // prepend the level to the message
    record.setMessage(record.getLevel().getName() + ": " + record.getMessage());
    if (record.getLevel().intValue() > Level.INFO.intValue()) {
        record.setLevel(Level.INFO);
    }
    
    return true;
});

[amamounelsayed]

Thank you so much @tonto7973 and your explanation for duplication is correct. We are working on aligning these two experiences. Thank you for sharing the info.

[TsuyoshiUshio]

Hi @tonto7973 I tried to reproduce this issue, however, I couldn't. Could you help me to reproduce it?

Could you share these info with us?

1. Plan (Consumption, AppService, Premium?)
2. OS (Probably windows)
3. Runtime version

Do you still have the same issue now?

[amamounelsayed]

@tonto7973 can you please also share your host.json file?

[tonto7973]

@TsuyoshiUshio, @amamounelsayed the issue still persists, logs are still duplicated in app insights.

I've created a sample project here.

Here are the details:

1. Plan: Consumption
2. OS: Windows
3. Runtime version: ~3 Stack: Java Java Version: 8

host.json:

{
  "version": "2.0",
  "extensionBundle": {
    "id": "Microsoft.Azure.Functions.ExtensionBundle",
    "version": "[1.*, 2.0.0)"
  } 
}

Azure Function Settings:

[
  {
    "name": "APPINSIGHTS_INSTRUMENTATIONKEY",
    "value": "c12f9edb...",
    "slotSetting": false
  },
  {
    "name": "APPLICATIONINSIGHTS_CONNECTION_STRING",
    "value": "InstrumentationKey=c12f9edb...",
    "slotSetting": false
  },
  {
    "name": "ApplicationInsightsAgent_EXTENSION_VERSION",
    "value": "~2",
    "slotSetting": false
  },
  {
    "name": "AzureWebJobsStorage",
    "value": "DefaultEndpointsProtocol=https;AccountName=09cbe5135baf4858bee9...",
    "slotSetting": false
  },
  {
    "name": "FUNCTIONS_EXTENSION_VERSION",
    "value": "~3",
    "slotSetting": false
  },
  {
    "name": "FUNCTIONS_WORKER_RUNTIME",
    "value": "java",
    "slotSetting": false
  },
  {
    "name": "WEBSITE_CONTENTAZUREFILECONNECTIONSTRING",
    "value": "DefaultEndpointsProtocol=https;AccountName=09cbe5135baf4858bee9...",
    "slotSetting": false
  },
  {
    "name": "WEBSITE_CONTENTSHARE",
    "value": "azure-function-examples-2009101024169624",
    "slotSetting": false
  },
  {
    "name": "WEBSITE_RUN_FROM_PACKAGE",
    "value": "1",
    "slotSetting": false
  },
  {
    "name": "XDT_MicrosoftApplicationInsights_Java",
    "value": "1",
    "slotSetting": false
  }
]

App Insight logs (duplicate logs highlighted in bold):

timestamp,message,severityLevel,itemType
"2020-09-10T09:47:56.6601788Z","Executing 'Functions.HttpTrigger-Java' (Reason='This function was programmatically called via the host APIs.', Id=0da012f4-c042-4aad-b67f-e8d85987d1c6)",1,trace
"2020-09-10T09:47:58.394Z","W: This is a warning arg1",2,trace
"2020-09-10T09:47:58.414Z","S: This is an error 123",3,trace
"2020-09-10T09:47:58.5958137Z","I: This is an info",1,trace
"2020-09-10T09:47:58.5962861Z","W: This is a warning {0}",2,trace
"2020-09-10T09:47:58.7652682Z","S: This is an error {0}",3,trace
"2020-09-10T09:47:58.765617Z","Function ""HttpTrigger-Java"" (Id: 0da012f4-c042-4aad-b67f-e8d85987d1c6) invoked by Java Worker",1,trace
"2020-09-10T09:47:58.9299472Z","Executed 'Functions.HttpTrigger-Java' (Succeeded, Id=0da012f4-c042-4aad-b67f-e8d85987d1c6, Duration=2329ms)",1,trace

[TsuyoshiUshio]

Thank you @tonto7973 I can repro it. I was dazed and confused by AppMap and Search, the duplication is removed but not for Monitoring > Log. We are discussing how to fix this issue. Probably, we are provide fix for it. Thank you for your report!

AppMap and Search

Monitoring > Log

[sschmeck]

I faced a similar issue, which I have documented at Configure Application Insights agent for Java Function Apps. The duplicated traces entries differ in timestamp, customDimensions, sdkVersion and itemId.

[kaibocai]

We just announced Distributed tracing public preivew 2. Please consider using the new appsetting mentioned in the link to enable distributed tracing. For public preview 2, the duplicate logs issue is fixed for execution context logger context.getLogger().

[ghost]

This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 4 days. It will be closed if no further activity occurs within 3 days of this comment.