Spring Boot Starter Live Metrics and Logback not working

[fox918]

Expected behavior

If a instrumentation key is provided, I expect the Application Insights Spring Boot Starter to send all
telemetry to Application Insights.
This includes Live-Metrics and all Logs as configured for the used logging implementation.

Actual behavior

Only custom events are transmitted to Application Insights.

To Reproduce

• Spring Boot Application using 2.1.3
• Add com.microsoft.azure:applicationinsights-spring-boot-starter:1.1.2 to dependencies
• Add com.microsoft.azure:applicationinsights-logging-logback:2.3.1 to dependencies
• Add some custom logging using @Autowired TelemetryClient telemetryClient; to the application
• Add a logback configuration to the classpath
• Add instrumentation key to configuration yaml:

azure:
  application-insights:
    instrumentation-key: xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxx
    channel:
      in-process:
        developer-mode: true

• start application and head over to Application Insights in the Azure Portal
• No logging metrics appear except the custom events in the "Search"Pane
• No connection to Live Metrics possible

Workaround

Creating a ApplicationInsights.xml in the classpath allows the metrics to be sent and
allows Live Metrics to be used (without any other change to the code or configuration).
Albeit this is a workaround that fixes the stated problem, it is quite inconvenient. Using
the configuration yaml files allows to easily provision different Instrumentation Keys for different
environments.

System information

Please provide the following information:

• Spring Boot: 2.1.3
• applicationinsights-spring-boot-starter: 1.1.2
• applicationinsights-logging-logback 2.3.1
• Windows 10
• Gradle as built script

Logs

In order not to spam only a short excerpt out of my log:
I find this line multiple time in the log, however the ikey does not match the Instrumentation Key provided in the configuration yaml:
04-03-2019 17:08:00.658 [DefaultQuickPulseCoordinator] DEBUG c.m.a.c.d.h.i.e.MainClientExec.log - Executing request POST /QuickPulseService.svc/ping?ikey=yyyyyyyy-yyyy-yyyy-yyyy-yyyyyyyyyy HTTP/1.1

If requested, I can also post a full log.

[dhaval24]

Expected behavior

If a instrumentation key is provided, I expect the Application Insights Spring Boot Starter to send all
telemetry to Application Insights.
This includes Live-Metrics and all Logs as configured for the used logging implementation.

Actual behavior

Only custom events are transmitted to Application Insights.

To Reproduce

• Spring Boot Application using 2.1.3
• Add com.microsoft.azure:applicationinsights-spring-boot-starter:1.1.2 to dependencies
• Add com.microsoft.azure:applicationinsights-logging-logback:2.3.1 to dependencies
• Add some custom logging using @Autowired TelemetryClient telemetryClient; to the application
• Add a logback configuration to the classpath

@fox918 did you add the AILogBack Appender in the logback configuration following https://docs.microsoft.com/en-us/azure/azure-monitor/app/java-trace-logs#add-the-appender-to-your-logging-framework ?

• Add instrumentation key to configuration yaml:

azure:
  application-insights:
    instrumentation-key: xxxxxxxx-xxxx-xxxx-xxxx-xxxxxxxxxx
    channel:
      in-process:
        developer-mode: true

You do not really need developer mode to be true except when testing.

• start application and head over to Application Insights in the Azure Portal
• No logging metrics appear except the custom events in the "Search"Pane

What do you mean by logging metrics? Logback logs appears as Trace events in Azure Portal. Can you please upload the Logback configuration file as well?

• No connection to Live Metrics possible

What do you see in Live Metrics blade? Can you paste screen shot?

Workaround

Creating a ApplicationInsights.xml in the classpath allows the metrics to be sent and
allows Live Metrics to be used (without any other change to the code or configuration).
Albeit this is a workaround that fixes the stated problem, it is quite inconvenient. Using
the configuration yaml files allows to easily provision different Instrumentation Keys for different
environments.

Application Insights Starter was designed to avoid using xml. I won't recommend using ApplicationInsights.xml in Springboot apps. It introduces other problems.

System information

Please provide the following information:

• Spring Boot: 2.1.3
• applicationinsights-spring-boot-starter: 1.1.2
• applicationinsights-logging-logback 2.3.1
• Windows 10
• Gradle as built script

Logs

In order not to spam only a short excerpt out of my log:
I find this line multiple time in the log, however the ikey does not match the Instrumentation Key provided in the configuration yaml:
04-03-2019 17:08:00.658 [DefaultQuickPulseCoordinator] DEBUG c.m.a.c.d.h.i.e.MainClientExec.log - Executing request POST /QuickPulseService.svc/ping?ikey=yyyyyyyy-yyyy-yyyy-yyyy-yyyyyyyyyy HTTP/1.1

If requested, I can also post a full log.

Please turn on debug logging for AI SDK by enabling the following property:
azure.application-insights.logger.level=trace
and provide the detailed sdk logs.

@fox918 as far as I know there is no known bug for live metrics in 1.1.2 version of starter.

[fox918]

Hi @dhaval24

Ok, I will try to answer your questions one by one:

1. Yes, the AI LogBack Appender is in the configuration. See my Logback configuration:

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{dd-MM-yyyy HH:mm:ss.SSS} %magenta([%thread]) %highlight(%-5level) %logger{36}.%M - %msg%n
            </pattern>
        </encoder>
    </appender>
    <appender name="aiAppender"
              class="com.microsoft.applicationinsights.logback.ApplicationInsightsAppender">
    </appender>
    <root level="info">
        <appender-ref ref="STDOUT"/>
    </root>
    <root level="info">
        <appender-ref ref="aiAppender"/>
    </root>
</configuration>

2. By Logging Metrics I mean all logs written to the appender and the metrics used for Live Metrics. I know that the log events appear as traces in the Application Insights pane on the Azure Portal. As I said, when providing ApplicationInsights.xml I do see all logs appearing as traces (including custom events). When ApplicationInsights.xml is missing, only custom events are shown/uploaded. (All viewed on Azure Portal under Investigate->Search)
   After some testing, I can confirm that some things are apparently uploaded, On Azure Portal in Investigate->Metrics I can see that CPU and Memory Usage is available.

3. The live metric panes shows: Not available: your app is offline or using an older SDK. I don't think a screenshot will explain this in more detail.

4. Yes, as I said I am aware that providing ApplicationInsights.xml is not the right way, however the application apparently fails to upload the logs except custom events to Application Insights if this file is not provided

5. Log:

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/
 :: Spring Boot ::        (v2.1.3.RELEASE)

05-03-2019 09:06:41.312 [restartedMain] INFO  c.company.portal.PortalApplication.logStarting - Starting PortalApplication on MCHBSLT361 with PID 2676 (C:\Users\fox918\IdeaProjects\portal\build\classes\java\main started by fox918in C:\Users\fox918\IdeaProjects\portal)
05-03-2019 09:06:41.359 [restartedMain] DEBUG c.company.portal.PortalApplication.logStarting - Running with Spring Boot v2.1.3.RELEASE, Spring v5.1.5.RELEASE
05-03-2019 09:06:41.359 [restartedMain] INFO  c.company.portal.PortalApplication.logStartupProfileInfo - The following profiles are active: dev
05-03-2019 09:06:41.421 [restartedMain] INFO  o.s.b.d.e.DevToolsPropertyDefaultsPostProcessor.logTo - Devtools property defaults active! Set 'spring.devtools.add-properties' to 'false' to disable
05-03-2019 09:06:41.421 [restartedMain] INFO  o.s.b.d.e.DevToolsPropertyDefaultsPostProcessor.logTo - For additional web related logging consider setting the 'logging.level.web' property to 'DEBUG'
05-03-2019 09:06:45.535 [restartedMain] INFO  o.s.b.w.e.tomcat.TomcatWebServer.initialize - Tomcat initialized with port(s): 9090 (http)
05-03-2019 09:06:45.566 [restartedMain] INFO  o.a.coyote.http11.Http11NioProtocol.log - Initializing ProtocolHandler ["http-nio-9090"]
05-03-2019 09:06:45.582 [restartedMain] INFO  o.a.catalina.core.StandardService.log - Starting service [Tomcat]
05-03-2019 09:06:45.582 [restartedMain] INFO  o.a.catalina.core.StandardEngine.log - Starting Servlet engine: [Apache Tomcat/9.0.16]
05-03-2019 09:06:45.597 [restartedMain] INFO  o.a.c.core.AprLifecycleListener.log - The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: [C:\Program Files\Java\jdk-11.0.1\bin;C:\WINDOWS\Sun\Java\bin;C:\WINDOWS\system32;C:\WINDOWS;C:\Program Files (x86)\Microsoft SDKs\Azure\CLI2\wbin;C:\ProgramData\DockerDesktop\version-bin;C:\Program Files\Docker\Docker\Resources\bin;C:\Program Files (x86)\Common Files\Oracle\Java\javapath;C:\WINDOWS\system32;C:\WINDOWS;C:\WINDOWS\System32\Wbem;C:\WINDOWS\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\Enterprise Vault\EVClient\;C:\Program Files\TortoiseGit\bin;C:\Program Files\Java\jdk-10.0.2;C:\Program Files\nodejs\;C:\Program Files\dotnet\;C:\Program Files (x86)\NVIDIA Corporation\PhysX\Common;C:\Program Files\NVIDIA Corporation\NVIDIA NvDLISR;C:\Program Files\Gource\cmd;C:\Go\bin;C:\Program Files (x86)\Yarn\bin\;]
05-03-2019 09:06:45.722 [restartedMain] INFO  o.a.c.c.C.[Tomcat].[localhost].[/].log - Initializing Spring embedded WebApplicationContext
05-03-2019 09:06:45.738 [restartedMain] INFO  o.s.web.context.ContextLoader.prepareWebApplicationContext - Root WebApplicationContext: initialization completed in 4317 ms
AI: TRACE 05-03-2019 08:06:45.832+0000, 24(restartedMain): Registering PC 'DeadLockDetector'
AI: TRACE 05-03-2019 08:06:45.832+0000, 24(restartedMain): Failed to store performance counter 'DeadLockDetector', since there is already one
AI: TRACE 05-03-2019 08:06:45.832+0000, 24(restartedMain): Registering PC 'JvmHeapMemoryUsedPerformanceCounter'
AI: TRACE 05-03-2019 08:06:45.832+0000, 24(restartedMain): Failed to store performance counter 'JvmHeapMemoryUsedPerformanceCounter', since there is already one
AI: ERROR 05-03-2019 08:06:45.847+0000, 24(restartedMain): Failed to create WindowsPerformanceCounterAsPC: 'java.lang.Exception: Failed to register all built-in Windows performance counters.'
AI: TRACE 05-03-2019 08:06:45.847+0000, 24(restartedMain): Registering PC 'JSDK_ProcessMemoryPerformanceCounter'
AI: TRACE 05-03-2019 08:06:45.847+0000, 24(restartedMain): Failed to store performance counter 'JSDK_ProcessMemoryPerformanceCounter', since there is already one
AI: TRACE 05-03-2019 08:06:45.847+0000, 24(restartedMain): Registering PC 'JSDK_ProcessCpuPerformanceCounter'
AI: TRACE 05-03-2019 08:06:45.847+0000, 24(restartedMain): Failed to store performance counter 'JSDK_ProcessCpuPerformanceCounter', since there is already one
AI: ERROR 05-03-2019 08:06:45.847+0000, 24(restartedMain): Failed to create WindowsPerformanceCounterAsPC: 'java.lang.Exception: Failed to register all built-in Windows performance counters.'
AI: TRACE 05-03-2019 08:06:45.847+0000, 24(restartedMain): Registering PC 'JSDK_ProcessMemoryPerformanceCounter'
AI: TRACE 05-03-2019 08:06:45.847+0000, 24(restartedMain): Failed to store performance counter 'JSDK_ProcessMemoryPerformanceCounter', since there is already one
AI: TRACE 05-03-2019 08:06:45.847+0000, 24(restartedMain): Registering PC 'JSDK_ProcessCpuPerformanceCounter'
AI: TRACE 05-03-2019 08:06:45.847+0000, 24(restartedMain): Failed to store performance counter 'JSDK_ProcessCpuPerformanceCounter', since there is already one
AI: TRACE 05-03-2019 08:06:45.847+0000, 24(restartedMain): Registering PC 'DeadLockDetector'
AI: TRACE 05-03-2019 08:06:45.847+0000, 24(restartedMain): Failed to store performance counter 'DeadLockDetector', since there is already one
AI: TRACE 05-03-2019 08:06:45.847+0000, 24(restartedMain): Registering PC 'JvmHeapMemoryUsedPerformanceCounter'
AI: TRACE 05-03-2019 08:06:45.847+0000, 24(restartedMain): Failed to store performance counter 'JvmHeapMemoryUsedPerformanceCounter', since there is already one
AI: INFO 05-03-2019 08:06:46.082+0000, 24(restartedMain): Specified class com.microsoft.applicationinsights.agent.internal.coresync.AgentNotificationsHandler is not present on the classpath
AI: INFO 05-03-2019 08:06:46.082+0000, 24(restartedMain): Agent was not found. Skipping the agent registration in 0.670ms
05-03-2019 09:06:46.082 [restartedMain] DEBUG c.m.p.s.j.JWTAuthenticationTokenFilter.init - Filter 'authenticationTokenFilterBean' configured for use
05-03-2019 09:06:46.128 [restartedMain] INFO  c.m.p.c.DataSourceConfig$$EnhancerBySpringCGLIB$$dd49516b.dataSource - Building datasource using url:jdbc:postgresql://localhost:5432/portal and user db_user@db-portal
AI: INFO 05-03-2019 08:06:47.086+0000, 32(ActiveTransmissionNetworkOutput_1-0): Backoff has been reset.
WARNING: An illegal reflective access operation has occurred
WARNING: Illegal reflective access by org.jooq.tools.reflect.Reflect (file:/C:/Users/fox918/.gradle/caches/modules-2/files-2.1/org.jooq/jooq/3.11.9/f6d14a9c2a620778ff9c5ce6fc92fb3a2dc9e3ca/jooq-3.11.9.jar) to constructor java.lang.invoke.MethodHandles$Lookup(java.lang.Class)
WARNING: Please consider reporting this to the maintainers of org.jooq.tools.reflect.Reflect
WARNING: Use --illegal-access=warn to enable warnings of further illegal reflective access operations
WARNING: All illegal access operations will be denied in a future release
05-03-2019 09:06:47.481 [restartedMain] INFO  o.s.s.c.ThreadPoolTaskExecutor.initialize - Initializing ExecutorService 'clientInboundChannelExecutor'
05-03-2019 09:06:47.497 [restartedMain] INFO  o.s.s.c.ThreadPoolTaskExecutor.initialize - Initializing ExecutorService 'clientOutboundChannelExecutor'
05-03-2019 09:06:48.013 [restartedMain] INFO  o.s.s.web.DefaultSecurityFilterChain.<init> - Creating filter chain: any request, [org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter@33a9ec49, org.springframework.security.web.context.SecurityContextPersistenceFilter@20cd4f53, org.springframework.security.web.header.HeaderWriterFilter@1a1e484, org.springframework.web.filter.CorsFilter@4acd3ad5, org.springframework.security.web.authentication.logout.LogoutFilter@452169c9, com.company.portal.security.jwt.JWTAuthenticationTokenFilter@3f762a35, org.springframework.security.web.savedrequest.RequestCacheAwareFilter@64506000, org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter@33221eb1, org.springframework.security.web.authentication.AnonymousAuthenticationFilter@7d563756, org.springframework.security.web.session.SessionManagementFilter@39e14f65, org.springframework.security.web.access.ExceptionTranslationFilter@6d3eafad, org.springframework.security.web.access.intercept.FilterSecurityInterceptor@56231efb]
05-03-2019 09:06:48.290 [restartedMain] INFO  o.s.s.c.ThreadPoolTaskScheduler.initialize - Initializing ExecutorService 'messageBrokerTaskScheduler'
05-03-2019 09:06:48.325 [restartedMain] INFO  o.s.s.c.ThreadPoolTaskExecutor.initialize - Initializing ExecutorService 'brokerChannelExecutor'
05-03-2019 09:06:48.535 [restartedMain] INFO  o.f.c.i.license.VersionPrinter.info - Flyway Community Edition 5.2.4 by Boxfuse
05-03-2019 09:06:48.551 [restartedMain] INFO  com.zaxxer.hikari.HikariDataSource.getConnection - HikariPool-1 - Starting...
05-03-2019 09:06:48.723 [restartedMain] INFO  com.zaxxer.hikari.HikariDataSource.getConnection - HikariPool-1 - Start completed.
05-03-2019 09:06:48.738 [restartedMain] INFO  o.f.c.i.database.DatabaseFactory.info - Database: jdbc:postgresql://localhost:5432/portal (PostgreSQL 9.6)
05-03-2019 09:06:49.450 [restartedMain] INFO  o.f.core.internal.command.DbClean.info - Successfully cleaned schema "public" (execution time 00:00.590s)
05-03-2019 09:06:49.497 [restartedMain] INFO  o.f.core.internal.command.DbValidate.info - Successfully validated 1 migration (execution time 00:00.023s)
05-03-2019 09:06:49.512 [restartedMain] INFO  o.f.c.i.s.JdbcTableSchemaHistory.info - Creating Schema History table: "public"."flyway_schema_history"
05-03-2019 09:06:49.622 [restartedMain] INFO  o.f.core.internal.command.DbMigrate.info - Current version of schema "public": << Empty Schema >>
05-03-2019 09:06:49.622 [restartedMain] INFO  o.f.core.internal.command.DbMigrate.info - Migrating schema "public" to version 1 - init database
05-03-2019 09:06:50.137 [restartedMain] INFO  o.f.core.internal.command.DbMigrate.info - Successfully applied 1 migration to schema "public" (execution time 00:00.632s)
05-03-2019 09:06:50.137 [restartedMain] INFO  o.f.c.i.c.SqlScriptCallbackFactory.info - Executing SQL callback: afterMigrate
05-03-2019 09:06:50.425 [restartedMain] INFO  o.s.b.d.a.OptionalLiveReloadServer.startServer - LiveReload server is running on port 35729
05-03-2019 09:06:50.503 [restartedMain] INFO  o.s.m.s.b.SimpleBrokerMessageHandler.info - Starting...
05-03-2019 09:06:50.503 [restartedMain] INFO  o.s.m.s.b.SimpleBrokerMessageHandler.info - BrokerAvailabilityEvent[available=true, SimpleBrokerMessageHandler [DefaultSubscriptionRegistry[cache[0 destination(s)], registry[0 sessions]]]]
05-03-2019 09:06:50.503 [restartedMain] INFO  o.s.m.s.b.SimpleBrokerMessageHandler.info - Started.
05-03-2019 09:06:50.519 [restartedMain] INFO  o.a.coyote.http11.Http11NioProtocol.log - Starting ProtocolHandler ["http-nio-9090"]
05-03-2019 09:06:50.550 [restartedMain] INFO  o.s.b.w.e.tomcat.TomcatWebServer.start - Tomcat started on port(s): 9090 (http) with context path ''
05-03-2019 09:06:50.550 [restartedMain] INFO  c.company.portal.PortalApplication.logStarted - Started PortalApplication in 9.795 seconds (JVM running for 20.176)
05-03-2019 09:06:50.910 [restartedMain] INFO  org.jooq.Constants.info - 
                                      
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
@@@@@@@@@@@@@@@@  @@        @@@@@@@@@@
@@@@@@@@@@@@@@@@@@@@        @@@@@@@@@@
@@@@@@@@@@@@@@@@  @@  @@    @@@@@@@@@@
@@@@@@@@@@  @@@@  @@  @@    @@@@@@@@@@
@@@@@@@@@@        @@        @@@@@@@@@@
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
@@@@@@@@@@        @@        @@@@@@@@@@
@@@@@@@@@@    @@  @@  @@@@  @@@@@@@@@@
@@@@@@@@@@    @@  @@  @@@@  @@@@@@@@@@
@@@@@@@@@@        @@  @  @  @@@@@@@@@@
@@@@@@@@@@        @@        @@@@@@@@@@
@@@@@@@@@@@@@@@@@@@@@@@  @@@@@@@@@@@@@
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@
@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@  Thank you for using jOOQ 3.11.9
                                      
05-03-2019 09:06:51.212 [restartedMain] INFO  o.s.s.a.AnnotationAsyncExecutionInterceptor.getDefaultExecutor - More than one TaskExecutor bean found within the context, and none is named 'taskExecutor'. Mark one of them as primary or name it 'taskExecutor' (possibly as an alias) in order to use it for async processing: [clientInboundChannelExecutor, clientOutboundChannelExecutor, brokerChannelExecutor, messageBrokerTaskScheduler]
AI: INFO 05-03-2019 08:06:52.693+0000, 82(ActiveTransmissionNetworkOutput_1-1): Backoff has been reset.
AI: INFO 05-03-2019 08:06:56.765+0000, 83(ActiveTransmissionNetworkOutput_2-0): Backoff has been reset.
AI: TRACE 05-03-2019 08:07:40.628+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '0.0'
AI: TRACE 05-03-2019 08:07:40.628+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '0.0'
AI: TRACE 05-03-2019 08:07:40.644+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '1.688301568E9'
AI: TRACE 05-03-2019 08:07:40.644+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 2.07367808E8
AI: INFO 05-03-2019 08:07:46.144+0000, 85(ActiveTransmissionNetworkOutput_2-1): Backoff has been reset.
05-03-2019 09:07:48.348 [MessageBroker-1] INFO  o.s.w.s.c.WebSocketMessageBrokerStats.lambda$initLoggingTask$0 - WebSocketSession[0 current WS(0)-HttpStream(0)-HttpPoll(0), 0 total, 0 closed abnormally (0 connect failure, 0 send limit, 0 transport error)], stompSubProtocol[processed CONNECT(0)-CONNECTED(0)-DISCONNECT(0)], stompBrokerRelay[null], inboundChannel[pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0], outboundChannel[pool size = 0, active threads = 0, queued tasks = 0, completed tasks = 0], sockJsScheduler[pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0]
AI: INFO 05-03-2019 08:07:53.768+0000, 87(ActiveTransmissionNetworkOutput_1-2): Backoff has been reset.
AI: TRACE 05-03-2019 08:08:40.605+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '244.89930725097656'
AI: TRACE 05-03-2019 08:08:40.606+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '14.039072036743164'
AI: TRACE 05-03-2019 08:08:40.607+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '1.516552192E9'
AI: TRACE 05-03-2019 08:08:40.607+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.67886584E8
AI: TRACE 05-03-2019 08:08:40.608+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.8924923284747006
AI: INFO 05-03-2019 08:08:45.894+0000, 88(ActiveTransmissionNetworkOutput_2-2): Backoff has been reset.
AI: TRACE 05-03-2019 08:09:40.593+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '15.636567115783691'
AI: TRACE 05-03-2019 08:09:40.594+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '10.557631492614746'
AI: TRACE 05-03-2019 08:09:40.595+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '1.510117376E9'
AI: TRACE 05-03-2019 08:09:40.595+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.88128784E8
AI: TRACE 05-03-2019 08:09:40.596+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.7683700345063261
AI: INFO 05-03-2019 08:09:45.853+0000, 89(ActiveTransmissionNetworkOutput_2-3): Backoff has been reset.
AI: TRACE 05-03-2019 08:10:40.593+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '15.631293296813965'
AI: TRACE 05-03-2019 08:10:40.593+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '9.29089641571045'
AI: TRACE 05-03-2019 08:10:40.593+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '1.457524736E9'
AI: TRACE 05-03-2019 08:10:40.593+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.72373952E8
AI: TRACE 05-03-2019 08:10:40.593+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.7843352690250446
AI: INFO 05-03-2019 08:10:45.856+0000, 90(ActiveTransmissionNetworkOutput_2-4): Backoff has been reset.
AI: TRACE 05-03-2019 08:11:40.587+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '15.602556228637695'
AI: TRACE 05-03-2019 08:11:40.588+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '9.462139129638672'
AI: TRACE 05-03-2019 08:11:40.588+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '1.91236096E9'
AI: TRACE 05-03-2019 08:11:40.589+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.9143564E8
AI: TRACE 05-03-2019 08:11:40.589+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.7326416675002501
AI: INFO 05-03-2019 08:11:46.049+0000, 91(ActiveTransmissionNetworkOutput_2-5): Backoff has been reset.
AI: TRACE 05-03-2019 08:12:40.586+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '15.58350658416748'
AI: TRACE 05-03-2019 08:12:40.587+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '8.372955322265625'
AI: TRACE 05-03-2019 08:12:40.587+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '1.880276992E9'
AI: TRACE 05-03-2019 08:12:40.587+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 2.1039676E8
AI: TRACE 05-03-2019 08:12:40.588+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.732421875
AI: INFO 05-03-2019 08:12:45.997+0000, 92(ActiveTransmissionNetworkOutput_2-6): Backoff has been reset.
AI: TRACE 05-03-2019 08:13:40.599+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '15.46425724029541'
AI: TRACE 05-03-2019 08:13:40.602+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '6.296662330627441'
AI: TRACE 05-03-2019 08:13:40.603+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '1.823813632E9'
AI: TRACE 05-03-2019 08:13:40.604+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.81174136E8
AI: TRACE 05-03-2019 08:13:40.605+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.7582487045337154
AI: INFO 05-03-2019 08:13:45.860+0000, 83(ActiveTransmissionNetworkOutput_2-0): Backoff has been reset.
AI: TRACE 05-03-2019 08:14:40.597+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '15.600274085998535'
AI: TRACE 05-03-2019 08:14:40.599+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '4.750572204589844'
AI: TRACE 05-03-2019 08:14:40.600+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '1.860169728E9'
AI: TRACE 05-03-2019 08:14:40.601+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.99102456E8
AI: TRACE 05-03-2019 08:14:40.602+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.7487103951732529
AI: INFO 05-03-2019 08:14:45.888+0000, 85(ActiveTransmissionNetworkOutput_2-1): Backoff has been reset.
AI: TRACE 05-03-2019 08:15:40.586+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '15.615967750549316'
AI: TRACE 05-03-2019 08:15:40.586+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '6.9078145027160645'
AI: TRACE 05-03-2019 08:15:40.586+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '1.881731072E9'
AI: TRACE 05-03-2019 08:15:40.586+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.66710984E8
AI: TRACE 05-03-2019 08:15:40.586+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.7780596299691641
AI: INFO 05-03-2019 08:15:45.874+0000, 88(ActiveTransmissionNetworkOutput_2-2): Backoff has been reset.
AI: TRACE 05-03-2019 08:16:40.586+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '15.633954048156738'
AI: TRACE 05-03-2019 08:16:40.586+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '6.692615509033203'
AI: TRACE 05-03-2019 08:16:40.586+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '2.045108224E9'
AI: TRACE 05-03-2019 08:16:40.586+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.85798704E8
AI: TRACE 05-03-2019 08:16:40.586+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.7812890644532227
AI: INFO 05-03-2019 08:16:45.906+0000, 89(ActiveTransmissionNetworkOutput_2-3): Backoff has been reset.
AI: TRACE 05-03-2019 08:17:40.584+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '15.616381645202637'
AI: TRACE 05-03-2019 08:17:40.584+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '7.288242340087891'
AI: TRACE 05-03-2019 08:17:40.584+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '2.007535616E9'
AI: TRACE 05-03-2019 08:17:40.584+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 2.04747736E8
AI: TRACE 05-03-2019 08:17:40.584+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.7324096681721971
AI: INFO 05-03-2019 08:17:45.827+0000, 90(ActiveTransmissionNetworkOutput_2-4): Backoff has been reset.
AI: TRACE 05-03-2019 08:18:40.577+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '15.617783546447754'
AI: TRACE 05-03-2019 08:18:40.577+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '8.489850997924805'
AI: TRACE 05-03-2019 08:18:40.577+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '1.958219776E9'
AI: TRACE 05-03-2019 08:18:40.577+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.69135584E8
AI: TRACE 05-03-2019 08:18:40.577+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.7487353534343384
AI: INFO 05-03-2019 08:18:46.038+0000, 91(ActiveTransmissionNetworkOutput_2-5): Backoff has been reset.
AI: TRACE 05-03-2019 08:19:40.595+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '15.615124702453613'
AI: TRACE 05-03-2019 08:19:40.595+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '6.6708984375'
AI: TRACE 05-03-2019 08:19:40.595+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '1.978322944E9'
AI: TRACE 05-03-2019 08:19:40.595+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.88094792E8
AI: TRACE 05-03-2019 08:19:40.595+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.7941120109311471
AI: INFO 05-03-2019 08:19:46.126+0000, 92(ActiveTransmissionNetworkOutput_2-6): Backoff has been reset.
AI: TRACE 05-03-2019 08:20:40.591+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '15.533215522766113'
AI: TRACE 05-03-2019 08:20:40.591+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '6.673686981201172'
AI: TRACE 05-03-2019 08:20:40.591+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '1.978179584E9'
AI: TRACE 05-03-2019 08:20:40.591+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 2.07020544E8
AI: TRACE 05-03-2019 08:20:40.591+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.7649739583333334
AI: INFO 05-03-2019 08:20:45.971+0000, 83(ActiveTransmissionNetworkOutput_2-0): Backoff has been reset.
AI: TRACE 05-03-2019 08:21:40.594+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '30.20149803161621'
AI: TRACE 05-03-2019 08:21:40.594+0000, 20(HeartBeatProvider_heartBeatSenderService-0): No of heartbeats sent, 1
AI: TRACE 05-03-2019 08:21:40.596+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '7.763715744018555'
AI: TRACE 05-03-2019 08:21:40.597+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '2.223108096E9'
AI: TRACE 05-03-2019 08:21:40.597+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.70457912E8
AI: TRACE 05-03-2019 08:21:40.599+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.7552335077835928
AI: INFO 05-03-2019 08:21:46.020+0000, 85(ActiveTransmissionNetworkOutput_2-1): Backoff has been reset.
AI: TRACE 05-03-2019 08:22:40.593+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '19.11627769470215'
AI: TRACE 05-03-2019 08:22:40.593+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '6.393035888671875'
AI: TRACE 05-03-2019 08:22:40.593+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '2.173657088E9'
AI: TRACE 05-03-2019 08:22:40.593+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 1.89370936E8
AI: TRACE 05-03-2019 08:22:40.593+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.771484375
AI: INFO 05-03-2019 08:22:45.841+0000, 88(ActiveTransmissionNetworkOutput_2-2): Backoff has been reset.
AI: TRACE 05-03-2019 08:23:40.597+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Process IO Data Bytes/sec'(Process, IO Data Bytes/sec, java#2): '15.482393264770508'
AI: TRACE 05-03-2019 08:23:40.597+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Processor % Processor Time'(Processor, % Processor Time, _Total): '6.896779537200928'
AI: TRACE 05-03-2019 08:23:40.597+0000, 21(PerformanceCounterContainer-0): Sent performance counter for 'Memory Available Bytes'(Memory, Available Bytes, ): '2.172227584E9'
AI: TRACE 05-03-2019 08:23:40.597+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process Private Bytes: 2.07306568E8
AI: TRACE 05-03-2019 08:23:40.597+0000, 21(PerformanceCounterContainer-0): Performance Counter: Process % Processor Time: 0.7909628941403907
AI: INFO 05-03-2019 08:23:45.891+0000, 89(ActiveTransmissionNetworkOutput_2-3): Backoff has been reset.

[JRiggenbach]

I am unable to get any data from my spring boot application into the live stream as well. I'm seeing telemetry events within the Azure Portal, but the live stream is saying that I need to upgrade my sdk as well.

AI trace logs
AI: TRACE 05-03-2019 23:09:20.068+0000, 75(http-nio-8080-exec-1): InstrumentationKeyResolver - pending resolution of instrumentation key: 0a07e0b0-8e7f-4c01-9d1f-da34910e49a6
AI: TRACE 05-03-2019 23:09:20.098+0000, 75(http-nio-8080-exec-1): Application correlation Id could not be retrieved (e.g. task may be pending or failed)
AI: INFO 05-03-2019 23:09:20.228+0000, 75(http-nio-8080-exec-1): Skip resolving request source as the following header was not found: Request-Context

Also, any chance I can get some direction on who to ask about the azure-spring-boot-metrics-starter package? The MS documentation lead me to believe that all I had to do was add this dependency, add the instrumentation key and that would get me running with pre-aggregated metrics auto collected to Azure Monitor. I can't seem to find any JVM related info in Azure Monitor; which lead to see if I could see anything being sent in the Live Stream, which now I'm posting this comment :)

[dhaval24]

@JRiggenbach can you please create a seperate issue for metrics starter on https://github.com/Microsoft/azure-spring-boot I will respond there as I was the one who worked on it. Most likely you are looking at incorrect place in the portal.

Another, the banner you are seeing is false banner. That is UI issue that should be fixed on Azure side. once you click ok on that do you see any data?

[JRiggenbach]

@dhaval24 Issue created under spring boot
microsoft/azure-spring-boot#608

As for the false banner...not sure what "ok" I'm suppose to click on

[dhaval24]

@JRiggenbach this is not the banner which I was thinking of. Yes it seems live metrics is not enabled. Seems suspicious to me. Are you on starter 1.1.2? Is it possible to upload your sample code on github somewhere so I can look at instrumentation?

[dhaval24]

@fox918 and @JRiggenbach I cannot reproduce this issue on my end yet, if you can provide a minimal repro of it, I can take a look locally.

[fox918]

While creating the minimal example, I might have discovered the root cause of our problem.
There might be a dependency problem between the Spring Boot Starters for Azure Keyvault and Application Insights.
Our application uses the Azure Keyvault to store its application secrets.

When I remove the Keyvault from the dependencies, the live metrics and traces (log messages) on Application Insights will work.

I created a minimal working example:
https://github.com/fox918/AppInsightsPrototype

@JRiggenbach maybe you can try to remove the dependency on azure-spring-boot-metrics-starter in your application for a test if Application Insights work if this dependency is removed.

It might be a depency problem between https://github.com/Microsoft/azure-spring-boot and the Spring Boot Application Insights Starter

[JRiggenbach]

@fox918 Following your minimal example approach, I'm not have any issue with getting data to show in the live stream. My sample application has the spring boot starters for Azure Keyvault and App Insights, along with many other azure dependencies, and the live stream is working. I still can't get my real application to show in the live stream however...still digging....

[dhaval24]

@JRiggenbach one quick question - do you run this springboot app in self contained tomcat? Or do you deploy on tomcat service? Does your production environment have any sort of firewall restriction?

You can also try to attach some network tool and see if the traffic goes to "Quickpulse"

[fox918]

Ok, I played around with my minimal example and I still think it is some sort of dependency problem.

Updating the Key Vault dependency from 2.1.3 to 2.1.4 seems to make the minimal example working.

So there most likely is some sort of dependency trouble in regards to the Spring Boot Starters and the Application Insights Starter.

For me, the issue is solved, I'm leaving the issue open for @JRiggenbach

[JRiggenbach]

I believe I'm experience the same thing here. I have a Maven aggregate project so when I move some of these dependencies around higher in the chain, they start to work, also while breaking other things since they overwrite older dependencies. Either way, once I get my dependencies unwound, I think this will work.

Feel free to close this issue.