URLs in requests with spaces produce Exception in applicationinsights-agent-3.0.0-PREVIEW.5

[vchernogorov]

Expected behavior

I expect that telemetry for requests with spaces in the URL will be handled well.

Actual behavior

I see and ERROR in the agent's logs: Illegal character in query at index 64: https://graph.microsoft.com/v1.0/servicePrincipals?$filter=appId eq '<UUID>'. And I don't see the request in Azure Search dashboard.

To Reproduce

Steps to reproduce the behavior:

0. Setup logging output of the agent to the file like so:

   {
   "instrumentationSettings": {
   "preview": {
     "selfDiagnostics": {
       "destination": "file",
       "directory": "/var/log/applicationinsights",
       "level": "INFO",
       "maxSizeMB": 10
     }
   }
   }
   }

1. Run your application with java -javaagent:path/to/applicationinsights-agent-3.0.0-PREVIEW.5 -jar app.jar command.
2. tail -f /var/log/applicationinsights/applicationinsights.log

System information

Please provide the following information:

• SDK Version: applicationinsights-agent-3.0.0-PREVIEW.5
• OS type and version: macOS Catalina 10.15.5 (19F101)
• Application Server type and version (if applicable): org.apache.tomcat.emded:tomcat-embed-core:9.0.36
• Using spring-boot? 2.3.1-RELEASE
• Additional relevant libraries (with version, if applicable):

  implementation "com.microsoft.azure:applicationinsights-spring-boot-starter:2.6.1"
  implementation "com.microsoft.azure:applicationinsights-logging-logback:2.6.1"
  implementation 'com.microsoft.azure:azure-spring-boot-metrics-starter:2.3.2'

Logs

2020-07-24 00:59:01.371+04 WARN  c.m.a.i.c.c.ConnectionString - Connection string is overriding previously configured instrumentation key.
2020-07-24 00:59:01.384+04 INFO  c.m.a.internal.util.LimitsEnforcer - 'MaxTelemetryBufferCapacity': null value is replaced with '%d'
2020-07-24 00:59:01.385+04 INFO  c.m.a.internal.util.LimitsEnforcer - 'FlushIntervalInSeconds': null value is replaced with '%d'
2020-07-24 00:59:01.385+04 INFO  c.m.a.internal.util.LimitsEnforcer - 'MaxTelemetryBufferCapacity': null value is replaced with '%d'
2020-07-24 00:59:01.385+04 INFO  c.m.a.internal.util.LimitsEnforcer - 'FlushIntervalInSeconds': null value is replaced with '%d'
2020-07-24 00:59:01.418+04 INFO  c.m.a.internal.util.LimitsEnforcer - 'Channel.MaxTransmissionStorageCapacityInMB': null value is replaced with '%d'
2020-07-24 00:59:01.480+04 INFO  c.m.a.i.heartbeat.HeartBeatModule - heartbeat is enabled
2020-07-24 00:59:01.497+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_ProcessIOPerformanceCounter: Error in file '/proc/10193/io': Can not read
2020-07-24 00:59:01.498+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_TotalCpuPerformanceCounter: Error in file '/proc/stat': Can not read
2020-07-24 00:59:03.473+04 INFO  a.extension.diagnostics - Application Insights Codeless Agent Attach Successful
2020-07-24 00:59:29.271+04 ERROR c.m.a.agent.Exporter - Illegal character in query at index 101: http://msd365fp-mr-dev-storage-westus.documents.azure.com/addresses/?$resolveFor=dbs&$filter=protocol eq rntbd
2020-07-24 00:59:36.654+04 ERROR c.m.a.agent.Exporter - Illegal character in query at index 134: http://msd365fp-mr-dev-storage-westus.documents.azure.com/addresses/?$resolveFor=dbs/01JqAA==/colls/01JqAJ3u+8c=/docs&$filter=protocol eq rntbd&$partitionKeyRangeIds=0
2020-07-24 01:00:01.495+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_ProcessIOPerformanceCounter: Error in file '/proc/10193/io': Error while parsing file: '%s'
2020-07-24 01:00:01.495+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_TotalCpuPerformanceCounter: Error in file '/proc/stat': Error while parsing file: '%s'
2020-07-24 01:00:02.150+04 ERROR c.m.a.agent.Exporter - Illegal character in query at index 134: http://msd365fp-mr-dev-storage-westus.documents.azure.com/addresses/?$resolveFor=dbs/01JqAA==/colls/01JqAKtDHxM=/docs&$filter=protocol eq rntbd&$partitionKeyRangeIds=0
2020-07-24 01:00:04.719+04 ERROR c.m.a.agent.Exporter - Illegal character in query at index 134: http://msd365fp-mr-dev-storage-westus.documents.azure.com/addresses/?$resolveFor=dbs/01JqAA==/colls/01JqAKtDHxM=/docs&$filter=protocol eq rntbd&$partitionKeyRangeIds=0
2020-07-24 01:00:05.267+04 ERROR c.m.a.agent.Exporter - Illegal character in query at index 134: http://msd365fp-mr-dev-storage-westus.documents.azure.com/addresses/?$resolveFor=dbs/01JqAA==/colls/01JqAPQPM-E=/docs&$filter=protocol eq rntbd&$partitionKeyRangeIds=0
2020-07-24 01:00:05.770+04 ERROR c.m.a.agent.Exporter - Illegal character in query at index 63: http://graph.microsoft.com/v1.0/servicePrincipals?$filter=appId eq '<UUID>'
2020-07-24 01:00:09.527+04 ERROR c.m.a.agent.Exporter - Illegal character in query at index 134: http://msd365fp-mr-dev-storage-westus.documents.azure.com/addresses/?$resolveFor=dbs/01JqAA==/colls/01JqAPQPM-E=/docs&$filter=protocol eq rntbd&$partitionKeyRangeIds=0
2020-07-24 01:01:01.494+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_ProcessIOPerformanceCounter: Error in file '/proc/10193/io': Error while parsing file: '%s'
2020-07-24 01:01:01.494+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_TotalCpuPerformanceCounter: Error in file '/proc/stat': Error while parsing file: '%s'
2020-07-24 01:02:01.495+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_ProcessIOPerformanceCounter: Error in file '/proc/10193/io': Error while parsing file: '%s'
2020-07-24 01:02:01.495+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_TotalCpuPerformanceCounter: Error in file '/proc/stat': Error while parsing file: '%s'
2020-07-24 01:03:01.496+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_ProcessIOPerformanceCounter: Error in file '/proc/10193/io': Error while parsing file: '%s'
2020-07-24 01:03:01.497+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_TotalCpuPerformanceCounter: Error in file '/proc/stat': Error while parsing file: '%s'
2020-07-24 01:04:01.498+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_ProcessIOPerformanceCounter: Error in file '/proc/10193/io': Error while parsing file: '%s'
2020-07-24 01:04:01.498+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_TotalCpuPerformanceCounter: Error in file '/proc/stat': Error while parsing file: '%s'
2020-07-24 01:05:01.498+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_ProcessIOPerformanceCounter: Error in file '/proc/10193/io': Error while parsing file: '%s'
2020-07-24 01:05:01.498+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_TotalCpuPerformanceCounter: Error in file '/proc/stat': Error while parsing file: '%s'
2020-07-24 01:06:01.500+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_ProcessIOPerformanceCounter: Error in file '/proc/10193/io': Error while parsing file: '%s'
2020-07-24 01:06:01.500+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_TotalCpuPerformanceCounter: Error in file '/proc/stat': Error while parsing file: '%s'
2020-07-24 01:07:01.499+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_ProcessIOPerformanceCounter: Error in file '/proc/10193/io': Error while parsing file: '%s'
2020-07-24 01:07:01.500+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_TotalCpuPerformanceCounter: Error in file '/proc/stat': Error while parsing file: '%s'
2020-07-24 01:08:01.500+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_ProcessIOPerformanceCounter: Error in file '/proc/10193/io': Error while parsing file: '%s'
2020-07-24 01:08:01.501+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_TotalCpuPerformanceCounter: Error in file '/proc/stat': Error while parsing file: '%s'
2020-07-24 01:09:01.505+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_ProcessIOPerformanceCounter: Error in file '/proc/10193/io': Error while parsing file: '%s'
2020-07-24 01:09:01.505+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_TotalCpuPerformanceCounter: Error in file '/proc/stat': Error while parsing file: '%s'
2020-07-24 01:10:01.503+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_ProcessIOPerformanceCounter: Error in file '/proc/10193/io': Error while parsing file: '%s'
2020-07-24 01:10:01.503+04 ERROR c.m.a.i.p.AbstractUnixPerformanceCounter - Performance Counter JSDK_TotalCpuPerformanceCounter: Error in file '/proc/stat': Error while parsing file: '%s'

[MS-jgol]

@vchernogorov Added this item to investigate, most likely it is a bug

[trask]

Hi @vchernogorov! What java library are you using that is generating these http requests?

http://msd365fp-mr-dev-storage-westus.documents.azure.com/addresses/?$resolveFor=dbs&$filter=protocol eq rntbd

We instrument several http clients (Apache HttpClient, Okhttp, HttpURLConnection, Netty) and trying to understand which one is causing this issue, and how we can reproduce the issue.

[jwyseu]

@trask I'm following this issue as I saw the same in our logs. We use spring boot 2.2.6.RELEASE with the embedded tomcat which is the default.

The request to the external system is done with org.apache.http.client (used by the OKTA sdk library to execute so I had to dig a bit)

[trask]

Thanks @jwyseu! Any chance you can pull out the particular code that is using Apache HttpClient in that case, so we can try to build a standalone repro?

[jwyseu]

Did a quick test if I could extract some code and I was able to reproduce it in a quite minimal way Using the dependency

org.apache.httpcomponents httpclient 4.5.10

I added the following code in a dummy spring RestController HttpClientBuilder httpClientBuilder = HttpClientBuilder.create(); CloseableHttpClient httpClient = httpClientBuilder.build();

    HttpRequestBase httpRequest = new HttpGet("http://google.be/?q=test%20request");
    HttpResponse httpResponse = httpClient.execute(httpRequest);

Which gives me the following log: 2020-09-24 08:15:26.989+02 ERROR c.m.a.agent.Exporter - Illegal character in query at index 24: http://google.be/?q=test request

Should I zip and send you the project sources?

[trask]

Nice! If you can zip and attach your repro that would be great!

[jwyseu]

Just enabled the self-diagnostics, which gives a bit more logging: 2020-09-24 08:23:47.454+02 DEBUG c.m.a.agent.Exporter - exporting span: SpanWrapper{delegate=io.opentelemetry.sdk.trace.RecordEventsReadableSpan@70847e54, resolvedLinks=[], resolvedEvents=[], attributes={net.peer.name=AttributeValueString{stringValue=google.be}, http.status_code=AttributeValueLong{longValue=200}, http.url=AttributeValueString{stringValue=http://google.be/?q=test request}, http.method=AttributeValueString{stringValue=GET}}, totalAttributeCount=4, totalRecordedEvents=0, status=Status{canonicalCode=OK, description=null}} 2020-09-24 08:23:47.455+02 ERROR c.m.a.agent.Exporter - Illegal character in query at index 24: http://google.be/?q=test request 2020-09-24 08:23:47.455+02 DEBUG c.m.a.agent.Exporter - Illegal character in query at index 24: http://google.be/?q=test request java.net.URISyntaxException: Illegal character in query at index 24: http://google.be/?q=test request at java.net.URI$Parser.fail(URI.java:2848) at java.net.URI$Parser.checkChars(URI.java:3021) at java.net.URI$Parser.parseHierarchical(URI.java:3111) at java.net.URI$Parser.parse(URI.java:3053) at java.net.URI.(URI.java:588) at com.microsoft.applicationinsights.agent.Exporter.applyHttpRequestSpan(Exporter.java:340) at com.microsoft.applicationinsights.agent.Exporter.exportRemoteDependency(Exporter.java:202) at com.microsoft.applicationinsights.agent.Exporter.export(Exporter.java:111) at com.microsoft.applicationinsights.agent.Exporter.export(Exporter.java:76) at io.opentelemetry.sdk.trace.export.SimpleSpanProcessor.onEnd(SimpleSpanProcessor.java:80) at io.opentelemetry.sdk.trace.MultiSpanProcessor.onEnd(MultiSpanProcessor.java:59) at io.opentelemetry.sdk.trace.RecordEventsReadableSpan.endInternal(RecordEventsReadableSpan.java:440) at io.opentelemetry.sdk.trace.RecordEventsReadableSpan.end(RecordEventsReadableSpan.java:422) at io.opentelemetry.auto.instrumentation.apachehttpclient.v4_0.ApacheHttpClientInstrumentation$HelperMethods.doMethodExit(ApacheHttpClientInstrumentation.java:204) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108) at com.transwide.insightssample.TestController.someDummyRequest(TestController.java:46) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190) at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138) at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:888) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:793) at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) at javax.servlet.http.HttpServlet.service(HttpServlet.java:634) at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:108) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:526) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:367) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:860) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1591) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:748)

[jwyseu]

Sample code sample.zip You'll still need to add the azure agent jar as I removed that from the azure folder.

[trask]

Thanks so much! we'll check it out tomorrow

[trask]

This is fixed now in Preview.7

[spaykit]

This also happens for a pipe sign '|'.

[trask]

Hi @spaykit, are you on Preview.7 already? What java library are you using that is generating these http requests?

We instrument several http clients (Apache HttpClient, Okhttp, HttpURLConnection, Netty) and need to understand which one is causing the issue, and also how we can reproduce the issue.

[spaykit]

Hi @trask, sorry that I mislead you, I'm using codeless attach for java via Azure App Service.

I'm using 'quarkus-rest-client' which uses 'RESTEasy' which uses 'Apache HttpClient'.

[INFO] +- io.quarkus:quarkus-rest-client:jar:1.8.3.Final:compile [INFO] | +- io.quarkus:quarkus-resteasy-common:jar:1.8.3.Final:compile [INFO] | | +- org.jboss.resteasy:resteasy-core:jar:4.5.6.Final:compile [INFO] | | | +- org.jboss.spec.javax.ws.rs:jboss-jaxrs-api_2.1_spec:jar:2.0.1.Final:compile [INFO] | | | +- org.jboss.resteasy:resteasy-core-spi:jar:4.5.6.Final:compile [INFO] | | | - com.ibm.async:asyncutil:jar:0.1.0:compile [INFO] | | - com.sun.activation:jakarta.activation:jar:1.2.1:compile [INFO] | +- org.jboss.resteasy:resteasy-client-microprofile:jar:4.5.6.Final:compile [INFO] | | +- org.jboss.resteasy:resteasy-client:jar:4.5.6.Final:compile [INFO] | | | - org.jboss.resteasy:resteasy-client-api:jar:4.5.6.Final:compile [INFO] | | - org.eclipse.microprofile.rest.client:microprofile-rest-client-api:jar:1.4.1:compile [INFO] | +- jakarta.interceptor:jakarta.interceptor-api:jar:1.2.5:compile [INFO] | +- org.apache.httpcomponents:httpasyncclient:jar:4.1.4:compile [INFO] | | - org.apache.httpcomponents:httpcore-nio:jar:4.4.13:compile [INFO] | - org.jboss.logging:commons-logging-jboss-logging:jar:1.0.0.Final:compile

Log 2020-10-18T00:08:17.336987725Z 2020-10-18 00:08:17.336Z ERROR c.m.a.agent.Exporter - Illegal character in query at index 111: https://liquipedia.net/dota2/api.php?format=json&api_version=3&action=askargs&conditions=Has_teams::Team_Secret|Has_map_date::>2020-10-18T00:00:00Z&printouts=Has+teamid|Has+region|Has+name|Has+team+left|Has+team+right|Modification+date|Is+active|Has+map+date|Has+timezone|Has+game+count|Has+exact+time|Has+team+left+score|Has+team+right+score|Has+tournament|Has+tournament+name|Has+tournament+tier|Has+winner|Is+finished|Is+map+number|Has+city|Has+country|Has+date|Has+start+date|Has+end+date|Has+start+patch|Has+end+patch|Has+game|Match+length&parameters=|sort=Has_map_date|order=desc

[trask]

No worries, that makes sense. I'm not sure rollout schedule for PREVIEW.7 on App Services, cc: @MS-jgol

[spaykit]

@MS-jgol , is there any plan to release a fix for codeless attach?

[MS-jgol]

@spaykit Application Insights Java 3.0 version will be in App Service some time during this Spring - this is largely due to release cycles. Meanwhile, you can use the standalone agent: https://docs.microsoft.com/en-us/azure/azure-monitor/app/java-in-process-agent