Sending Logback trace logs to Azure application insights - error: failed to send, bad request

6
votes

I have a Java web app in Azure that uses Logback for trace logging. I am trying to link up the trace logging to Application Insights in Azure and I have followed all of the instructions for doing so in the Azure documentation.

Here is the associated portion of the Maven pom.xml:

    <dependency>
        <groupId>com.microsoft.azure</groupId>
        <artifactId>applicationinsights-web</artifactId>
        <version>[1.0,)</version>
    </dependency>
    <dependency>
        <groupId>com.microsoft.azure</groupId>
        <artifactId>applicationinsights-core</artifactId>
        <version>[1.0,)</version>
    </dependency>
    <dependency>
        <groupId>com.microsoft.azure</groupId>
        <artifactId>applicationinsights-logging-logback</artifactId>
        <version>[1.0,)</version>
    </dependency>
  </dependencies>

  <repositories>
    <repository>
      <id>central</id>
      <name>Central</name>
      <url>http://repo1.maven.org/maven2</url>
    </repository>
  </repositories>

My ApplicationInsights.xml:

<?xml version="1.0" encoding="utf-8" standalone="no"?>
<!DOCTYPE xml>
<ApplicationInsights xmlns="http://schemas.microsoft.com/ApplicationInsights/2013/Settings" schemaVersion="2014-05-30">
  <SDKLogger />
  <InstrumentationKey>*my key here*</InstrumentationKey>
  <ContextInitializers>
  </ContextInitializers>
  <TelemetryInitializers>
    <Add type="com.microsoft.applicationinsights.web.extensibility.initializers.WebOperationIdTelemetryInitializer"/>
    <Add type="com.microsoft.applicationinsights.web.extensibility.initializers.WebOperationNameTelemetryInitializer"/>
    <Add type="com.microsoft.applicationinsights.web.extensibility.initializers.WebSessionTelemetryInitializer"/>
    <Add type="com.microsoft.applicationinsights.web.extensibility.initializers.WebUserTelemetryInitializer"/>
    <Add type="com.microsoft.applicationinsights.web.extensibility.initializers.WebUserAgentTelemetryInitializer"/>
  </TelemetryInitializers>
  <TelemetryModules>
    <Add type="com.microsoft.applicationinsights.web.extensibility.modules.WebRequestTrackingTelemetryModule"/>
    <Add type="com.microsoft.applicationinsights.web.extensibility.modules.WebSessionTrackingTelemetryModule"/>
    <Add type="com.microsoft.applicationinsights.web.extensibility.modules.WebUserTrackingTelemetryModule"/>    
  </TelemetryModules>
  <Channel>
    <!-- 
      Setting DeveloperMode to true will enable immediate transmission of the telemetry events, which can be helpful during the development process.
      Make sure to turn this off on production servers due to performance considerations.
    -->
    <DeveloperMode>true</DeveloperMode>
  </Channel>
  <DisableTelemetry>false</DisableTelemetry>
</ApplicationInsights>

My logback.xml:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE xml>

<configuration debug = "true">

    <appender class="ch.qos.logback.core.ConsoleAppender" name="STDOUT">
        <encoder>
            <Pattern>%d{HH:mm:ss.SSS} %-5level - %msg%n</Pattern>
        </encoder>
    </appender>

    <appender name="aiAppender" class="com.microsoft.applicationinsights.logback.ApplicationInsightsAppender">
    </appender>

    <root level="info">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="aiAppender"/>
    </root>

</configuration>

And my class that tests the logger and application insights integration:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import com.microsoft.applicationinsights.TelemetryClient;
/**
 * Hello world!
 *
 */
public class App 
{
    private final static Logger LOG = LoggerFactory.getLogger("root");
    public static void main( String[] args ) throws InterruptedException
    {
        LOG.info("Logging is working");
        TelemetryClient tc = new TelemetryClient();
        tc.trackTrace("Telemetry is working");
        System.out.println( "Hello World!" );
    }
}

When I run this, Logback works fine with the console appender, telemetry to application insights works fine, but the trace logs do not make it to the application insights portal. I get the following error:

AI: ERROR 18-10-2017 20:40, 19: Failed to send, Bad request : {"itemsReceived":1,"itemsAccepted":0,"errors":[{"index":0,"statusCode":400,"message":"SyntaxError: Unexpected token I"}]}

I have searched high and low for a solution to this problem, but I can't seem to work it out. Does anyone have any ideas? Thanks!!

Update:

Here is the full stack trace:

09:13:59,774 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
09:13:59,774 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
09:13:59,774 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/Users/greta/OneDrive/Eclipse%20Water%20Application%20Project%20Files/Test2/target/classes/logback.xml]
09:13:59,888 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
09:13:59,891 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
09:13:59,911 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
09:13:59,943 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [com.microsoft.applicationinsights.logback.ApplicationInsightsAppender]
09:13:59,988 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [aiAppender]
AI: INFO 20-10-2017 09:14, 1: Configuration file has been successfully found as resource
AI: INFO 20-10-2017 09:14, 1: 'MaxTelemetryBufferCapacity': null value is replaced with '500'
AI: INFO 20-10-2017 09:14, 1: 'FlushIntervalInSeconds': null value is replaced with '5'
AI: TRACE 20-10-2017 09:14, 1: Using Http Client version 4.3+
AI: INFO 20-10-2017 09:14, 1: 'Channel.MaxTransmissionStorageCapacityInMB': null value is replaced with '10'
AI: TRACE 20-10-2017 09:14, 1: C:\Users\greta\AppData\Local\Temp\AISDK\native\1.0.10 folder exists
AI: TRACE 20-10-2017 09:14, 1: Java process name is set to 'javaw'
AI: TRACE 20-10-2017 09:14, 1: Successfully loaded library 'applicationinsights-core-native-win64.dll'
AI: INFO 20-10-2017 09:14, 1: Configuration file has been successfully found as resource
AI: INFO 20-10-2017 09:14, 1: 'MaxTelemetryBufferCapacity': null value is replaced with '500'
AI: INFO 20-10-2017 09:14, 1: 'FlushIntervalInSeconds': null value is replaced with '5'
AI: INFO 20-10-2017 09:14, 1: 'Channel.MaxTransmissionStorageCapacityInMB': null value is replaced with '10'
AI: TRACE 20-10-2017 09:14, 1: C:\Users\greta\AppData\Local\Temp\AISDK\native\1.0.10 folder exists
AI: TRACE 20-10-2017 09:14, 1: Java process name is set to 'javaw'
AI: TRACE 20-10-2017 09:14, 1: Successfully loaded library 'applicationinsights-core-native-win64.dll'
AI: TRACE 20-10-2017 09:14, 1: Registering PC 'DeadLockDetector'
AI: TRACE 20-10-2017 09:14, 1: Registering PC 'JvmHeapMemoryUsedPerformanceCounter'
AI: TRACE 20-10-2017 09:14, 1: Registering PC 'JSDK_ProcessMemoryPerformanceCounter'
AI: TRACE 20-10-2017 09:14, 1: Registering PC 'JSDK_ProcessCpuPerformanceCounter'
AI: TRACE 20-10-2017 09:14, 1: Registering PC 'JSDK_WindowsPerformanceCounterAsPC'
AI: TRACE 20-10-2017 09:14, 1: Registering PC 'DeadLockDetector'
AI: TRACE 20-10-2017 09:14, 1: Failed to store performance counter 'DeadLockDetector', since there is already one
AI: TRACE 20-10-2017 09:14, 1: Registering PC 'JvmHeapMemoryUsedPerformanceCounter'
AI: TRACE 20-10-2017 09:14, 1: Failed to store performance counter 'JvmHeapMemoryUsedPerformanceCounter', since there is already one
AI: ERROR 20-10-2017 09:14, 1: Failed to create WindowsPerformanceCounterAsPC: 'Failed to register all built-in Windows performance counters.'
AI: TRACE 20-10-2017 09:14, 1: Registering PC 'JSDK_ProcessMemoryPerformanceCounter'
AI: TRACE 20-10-2017 09:14, 1: Failed to store performance counter 'JSDK_ProcessMemoryPerformanceCounter', since there is already one
AI: TRACE 20-10-2017 09:14, 1: Registering PC 'JSDK_ProcessCpuPerformanceCounter'
AI: TRACE 20-10-2017 09:14, 1: Failed to store performance counter 'JSDK_ProcessCpuPerformanceCounter', since there is already one
09:14:01,943 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
09:14:01,943 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
09:14:01,944 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [aiAppender] to Logger[ROOT]
09:14:01,944 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
09:14:01,945 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@6b415f5f - Registering current configuration as safe fallback point
09:13:59,774 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
09:13:59,774 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
09:13:59,774 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/C:/Users/greta/OneDrive/Eclipse%20Water%20Application%20Project%20Files/Test2/target/classes/logback.xml]
09:13:59,888 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
09:13:59,891 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
09:13:59,911 |-INFO in ch.qos.logback.core.joran.action.NestedComplexPropertyIA - Assuming default type [ch.qos.logback.classic.encoder.PatternLayoutEncoder] for [encoder] property
09:13:59,943 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [com.microsoft.applicationinsights.logback.ApplicationInsightsAppender]
09:13:59,988 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [aiAppender]
09:14:01,943 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to INFO
09:14:01,943 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
09:14:01,944 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [aiAppender] to Logger[ROOT]
09:14:01,944 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
09:14:01,945 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@6b415f5f - Registering current configuration as safe fallback point
09:14:01.948 INFO - Logging is working
AI: TRACE 20-10-2017 09:14, 1: InProcessTelemetryChannel sending telemetry
AI: TRACE 20-10-2017 09:14, 1: InProcessTelemetryChannel sending telemetry
Hello World!
AI: ERROR 20-10-2017 09:14, 19: Failed to send, Bad request : {"itemsReceived":1,"itemsAccepted":0,"errors":[{"index":0,"statusCode":400,"message":"SyntaxError: Unexpected token I"}]}

There are a few errors associated with the performance counter. I tried finding some info on these errors, but didn't have too much luck. Maybe that's part of the problem?

3
javaazurelogbackazure-application-insights
I tired to reproduce your issue.The test.class works fine locally?Would you please post your complete trace log? – Jay Gong
@JayGong, I added the stack trace as an update. Thanks for helping! – Greta

3 Answers

1
votes

One of the issues I can see here is that internal logger of AI is reporting unexpected character. I see that one of the possible issues is that there is some problem in the sanitization logic and that prevents the item to be sent to end point and hence you are not able to see the data on the portal. Also there are some known logback issues which are already mentioned on the github: https://github.com/Microsoft/ApplicationInsights-Java/issues/453 This should answer your question. Feel free to create another issue on Github if you wish to do so. Hopefully next public release should fix this.

1
votes

As an update, someone on the Windows Dev Center forum pointed out an entry on Github: https://github.com/Microsoft/ApplicationInsights-Java/issues/436. I downgraded to version 1.0.9 and this resolved my problem.

1
votes

The new version of Application Insights Java SDK 2.0.0-BETA is now released. Please try with to update your application dependency to the latest and try. I believe this issue is resolved with it. Also you get many latest features and bug fixes apart from this!