Hot questions for Using Azure in logback

Question:

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?


Answer:

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.

Question:

We are deploying a Spring MVC application using Spring Boot, to Azure Web App Service. We have the application deployed, and can hit the end points, but are unable to see logging output. Logging is implemented with a logback.xml file and the logging levels are set in the application.properties file.

Note that logging works perfectly when deploying the application to Tomcat on a VM. The logging output, when logged to stdout, is accessible in the catalina.out file. But, when the application is pushed to Azure Web App Services, no logging output is accessible from the catalina.log file, nor anywhere else.

Unfortunately, the documentation for deploying Spring Boot apps to azure can be summed up as 'scant to none', but we need to accomplish this for our customer. The documentation that is there, regarding logging for java, seems to want you to use Application Insights. Unfortunately, this is another service that costs money. There has to be a way to view standard logs from a java app in Azure Web App Services.

Is there anyone out there who has any experience with this? Much thanks in advance.


Answer:

Set the logging level within the application.properties file within Spring Boot.

logging.level=DEBUG
logging.level.org.springframework=DEBUG

Then within the web.config file set where the log whould be stored, i.e.

-Dlogging.file=&quot;%HOME%\LogFiles\boot.log&quot;

Then on the Console tab of the web application within Microsoft Azure you can specify that you would like to tail the log.

tail D:\home\LogFiles\boot.log

Question:

I have a java web app (springboot app) where in I want to push the logs to the application insights in azure. I am using logback as my logging framework as it is natively supported by Springboot. I followed the following blog for the integration of the applicationInsights for my web app.

https://github.com/AzureCAT-GSI/DevCamp/tree/master/HOL/java/06-appinsights

As per this blog I have created the following:

  1. created the application insights resource in azure
  2. created the filter in my java web app to capture the http requests
  3. created ApplicationInsights.xml
  4. created logback.xml which will have the AI appender provided by Azure.

here are the snippets from my web app

1) ApplicationInsight filter class is as follows:-

@Configuration

public class AppInsightsConfig {

    @Bean
    public String telemetryConfig() {
        String telemetryKey = System.getenv("APPLICATION_INSIGHTS_IKEY");
        if (telemetryKey != null) {
            TelemetryConfiguration.getActive().setInstrumentationKey(telemetryKey);
        }
        return telemetryKey;
    }

    @Bean
    @Order(1)
    public org.springframework.boot.web.servlet.FilterRegistrationBean aiFilterRegistration() {
        FilterRegistrationBean registration = new FilterRegistrationBean();
        registration.setFilter(new WebRequestTrackingFilter());
        registration.addUrlPatterns("/**");
        registration.setOrder(1);
        return registration;
    } 

    @Bean(name = "WebRequestTrackingFilter")
    public Filter WebRequestTrackingFilter() {
        return new WebRequestTrackingFilter();
    }   
}

2) ApplicationInsights.xml (src/main/resources folder)

<?xml version="1.0" encoding="UTF-8"?>
<ApplicationInsights xmlns="http://schemas.microsoft.com/ApplicationInsights/2013/Settings" schemaVersion="2014-05-30">


    <!-- The key from the portal: -->

    <InstrumentationKey>my app key</InstrumentationKey>


    <!-- HTTP request component (not required for bare API) -->

    <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>

    <!-- Events correlation (not required for bare API) -->
    <!-- These initializers add context data to each event -->

    <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>
    </ApplicationInsights>  

3) Logback.xml is as follows:-

<configuration>
    <appender name="aiAppender" 
        class="com.microsoft.applicationinsights.logback.ApplicationInsightsAppender">
    </appender>
    <root level="trace">
        <appender-ref ref="aiAppender" />
    </root>

    <logger name="org.springframework.web" level="INFO"/>
</configuration>

The issue is that I am not able to push the logs to the app insights. However I am able to get the telemetries in the app insights.

Note: I am using the latest versions of appinsights libraries (core and web)


Answer:

There seems to be a bug in azure library version 1.0.10. The fix is there in the next version 1.0.11. So to fix this, i downgraded the azure libraries to 1.0.9 and everything worked like a charm. The libraries application insights core/web/logback appender were down graded to 1.0.9 from 1.0.10.

The issue was only with logback appender. Log4j versions were behaving correctly with version 1.0.10.