ApplicationInsights-Java
ApplicationInsights-Java copied to clipboard
Reactor Netty HttpClient Wiretap Logs missing from tracing
Expected behavior
HttpClient log to be traced into Azure AppInsight when the wiretap is switched on.
HttpClient httpClient = HttpClient
.create()
.wiretap("reactor.netty.http.client.HttpClient",
LogLevel.DEBUG, AdvancedByteBufFormat.TEXTUAL);
Actual behavior
HttpClient log to be trace are missing from AppInsight tracing. We could see the logs been dumped from http client like
2022-11-23 20:52:39.129 DEBUG [app-name,,] 1 --- [or-http-epoll-3] reactor.netty.http.client.HttpClient : [bfdf3140-1, L:/10.22.xxx.xx:54830 - R:dev2xxxxxx.net.au/10.12.32.85:443] READ COMPLETE
2022-11-23 20:52:39.212 DEBUG [app-name,,] 1 --- [or-http-epoll-3] reactor.netty.http.client.HttpClient : [bfdf3140-1, L:/10.22.xxx.xx:54830 - R:dev2xxxxxx.net.au/10.12.32.85:443] READ: 8448B HTTP/1.1 200 OK
Transfer-Encoding: chunked
Content-Type: application/json
Request-Context: appId=cid-v1:xxxxxx
Strict-Transport-Security: max-age=15724800; includeSubDomains
Date: Wed, 23 Nov 2022 09:52:38 GMT
2000
{}
To Reproduce
Create a netty http client used with spring webflux and enable the http client loggings. Usage guide - https://www.baeldung.com/spring-log-webclient-calls#2-logging-with-netty-httpclient
System information
Please provide the following information:
- SDK Version: - applicationinsights-agent-3.4.2.jar
- OS type and version: Azure AKS
- Application Server type and version (if applicable):
- Using spring-boot? - Spring boot version - 2.7.4
- Additional relevant libraries (with version, if applicable):spring-boot-starter-webflux:2.7.4,JDK17
hi @mohitj13, are you already setting the Application Insights Java logging threshold to DEBUG?
check out docs at https://learn.microsoft.com/en-us/azure/azure-monitor/app/java-standalone-config#auto-collected-logging
@trask YES the Java logging threshold is set to DEBUG level
did you set it using APPLICATIONINSIGHTS_INSTRUMENTATION_LOGGING_LEVEL=DEBUG
or using below?
{
"instrumentation": {
"logging": {
"level": "DEBUG"
}
}
}
I have actually tried both to be honest. For now I am using - { "instrumentation": { "logging": { "level": "DEBUG" } } }
hi @mohitj13, I'm unable to reproduce this. Can you check out my repro at https://github.com/trask/wiretap-repro and see what might be different between it and what you are doing / seeing? thx!
This issue has been automatically marked as stale because it has been marked as requiring author feedback but has not had any activity for 7 days. It will be closed if no further activity occurs within 7 days of this comment.
Hi @trask
Apologies for this delay, please find the attached source replicated that is failing to track the logs to appinsights nettywiretap.zip
@mohitj13 can you include very exact repro steps?
I tried with your example, but was able to see wiretap logs getting captured when I hit the /users
url:
{"ver":1,"name":"Message","time":"2023-01-05T21:02:18.344Z","iKey":"afbcd285-0b88-4a9b-b6cf-7399d9ed28e8","tags":{"ai.internal.sdkVersion":"java:3.4.7","ai.cloud.roleInstance":"MININT-PLOJ2RD"},"data":{"baseType":"MessageData","baseData":{"ver":2,"message":"[3e3970fc-1, L:/192.168.86.193:63341 - R:reqres.in/172.67.73.173:443] READ: 1369B HTTP/1.1 200 OK\r\nDate: Thu, 05 Jan 2023 21:02:18 GMT\r\nContent-Type: application/json; charset=utf-8\r\nContent-Length: 996\r\nConnection: keep-alive\r\nX-Powered-By: Express\r\nAccess-Control-Allow-Origin: *\r\nEtag: W/"3e4-2RLXvr5wTg9YQ6aH95CkYoFNuO8"\r\nVia: 1.1 vegur\r\nCache-Control: max-age=14400\r\nCF-Cache-Status: HIT\r\nAge: 4070\r\nAccept-Ranges: bytes\r\nReport-To: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=U7NSIx%2FyC%2BJ98WMEJxiep%2B1d1MwDy%2FlPHVLAUKuApFLuy9AcExO3f%2F7hFH5ipfYfRzDEoTnG8qfPSydvVzB5H3PUflCBprL4M6Rn%2Bm4fTniUMEsJDRH3qgDOLA%3D%3D"}],"group":"cf-nel","max_age":604800}\r\nNEL: {"success_fraction":0,"report_to":"cf-nel","max_age":604800}\r\nServer: cloudflare\r\nCF-RAY: 784f27749a5ec5b0-SEA\r\n\r\n{"page":1,"per_page":6,"total":12,"total_pages":2,"data":[{"id":1,"email":"[email protected]","first_name":"George","last_name":"Bluth","avatar":"https://reqres.in/img/faces/1-image.jpg"},{"id":2,"email":"[email protected]","first_name":"Janet","last_name":"Weaver","avatar":"https://reqres.in/img/faces/2-image.jpg"},{"id":3,"email":"[email protected]","first_name":"Emma","last_name":"Wong","avatar":"https://reqres.in/img/faces/3-image.jpg"},{"id":4,"email":"[email protected]","first_name":"Eve","last_name":"Holt","avatar":"https://reqres.in/img/faces/4-image.jpg"},{"id":5,"email":"[email protected]","first_name":"Charle","severityLevel":"Verbose","properties":{"LoggerName":"reactor.netty.http.client.HttpClient","SourceType":"Logger","ThreadName":"reactor-http-nio-3"}}}}
HI @trask
Can you check into AppInsights traces on azure portal if it was capture there.
As when we look over an operation in azure portal these logs seems missing for it . Below is the snippet
AS we can see above in screenshot the above traces are not captured in the operation specific trace!
Hi @trask
If my understanding is correct the logs are not capture under operation is due to mdc are not attached to those logs probably - trace_id is not present as mdc on those logs probably hence missed.
`2023-01-06 11:24:48,902 INFO [http-nio-8080-exec-1] [trace_id=0d5a6eb926441333b0eb3e5653c701c4, trace_flags=01, span_id=781f29e4b6de6510] org.apache.juli.logging.DirectJDKLog: Initializing Spring DispatcherServlet 'dispatcherServlet' 2023-01-06 11:24:48,903 INFO [http-nio-8080-exec-1] [trace_id=0d5a6eb926441333b0eb3e5653c701c4, trace_flags=01, span_id=781f29e4b6de6510] org.springframework.web.servlet.FrameworkServlet: Initializing Servlet 'dispatcherServlet' 2023-01-06 11:24:48,905 INFO [http-nio-8080-exec-1] [trace_id=0d5a6eb926441333b0eb3e5653c701c4, trace_flags=01, span_id=781f29e4b6de6510] org.springframework.web.servlet.FrameworkServlet: Completed initialization in 0 ms 2023-01-06 11:24:48,967 INFO [http-nio-8080-exec-1] [trace_id=0d5a6eb926441333b0eb3e5653c701c4, trace_flags=01, span_id=781f29e4b6de6510] com.example.nettywiretap.controller.SampleController: Getting User list with details! 2023-01-06 11:24:49,470 DEBUG [reactor-http-nio-3] [trace_id=0d5a6eb926441333b0eb3e5653c701c4, trace_flags=01, span_id=781f29e4b6de6510] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e] REGISTERED 2023-01-06 11:24:49,650 DEBUG [reactor-http-nio-3] [trace_id=0d5a6eb926441333b0eb3e5653c701c4, trace_flags=01, span_id=781f29e4b6de6510] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e] CONNECT: reqres.in/104.26.10.213:443 2023-01-06 11:24:49,693 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e, L:/100.64.0.1:60737 - R:reqres.in/104.26.10.213:443] ACTIVE 2023-01-06 11:24:49,833 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e, L:/100.64.0.1:60737 - R:reqres.in/104.26.10.213:443] READ COMPLETE 2023-01-06 11:24:49,846 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e, L:/100.64.0.1:60737 - R:reqres.in/104.26.10.213:443] USER_EVENT: SslHandshakeCompletionEvent(SUCCESS) 2023-01-06 11:24:49,952 DEBUG [reactor-http-nio-3] [trace_id=da2fd89ba49846447e9dd5082afdb37c, trace_flags=01, span_id=84d95d1449249ff4] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e-1, L:/100.64.0.1:60737 - R:reqres.in/104.26.10.213:443] WRITE: 159B GET /api/users HTTP/1.1 user-agent: ReactorNetty/1.1.1 host: reqres.in accept: / traceparent: 00-da2fd89ba49846447e9dd5082afdb37c-84d95d1449249ff4-01
2023-01-06 11:24:49,957 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e-1, L:/100.64.0.1:60737 - R:reqres.in/104.26.10.213:443] FLUSH 2023-01-06 11:24:49,965 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e-1, L:/100.64.0.1:60737 - R:reqres.in/104.26.10.213:443] WRITE: 0B 2023-01-06 11:24:49,965 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e-1, L:/100.64.0.1:60737 - R:reqres.in/104.26.10.213:443] FLUSH 2023-01-06 11:24:49,967 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e-1, L:/100.64.0.1:60737 - R:reqres.in/104.26.10.213:443] READ COMPLETE 2023-01-06 11:24:49,975 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e-1, L:/100.64.0.1:60737 - R:reqres.in/104.26.10.213:443] READ: 1712B HTTP/1.1 200 OK Date: Fri, 06 Jan 2023 00:24:50 GMT Content-Type: application/json; charset=utf-8 Content-Length: 996 Connection: keep-alive X-Powered-By: Express Access-Control-Allow-Origin: * Etag: W/"3e4-2RLXvr5wTg9YQ6aH95CkYoFNuO8" Via: 1.1 vegur Cache-Control: max-age=14400 CF-Cache-Status: HIT Age: 6271 Accept-Ranges: bytes Report-To: {"endpoints":[{"url":"https://a.nel.cloudflare.com/report/v3?s=Q6T5gfusfJBDJ7RbPFznBnXBhaHMQ7m%2B7XqQLzn5Q18RwhvvR7WTW3Xuk2EOUNoCGj6wqi63HQIovqIScIV1JHl2OwCgoEtNQSlv2d9hKP1%2BNqXPUI1%2BReEFIg%3D%3D"}],"group":"cf-nel","max_age":604800} NEL: {"success_fraction":0,"report_to":"cf-nel","max_age":604800} Server: cloudflare CF-RAY: 78505020dc7e2b2c-MEL
{"page":1,"per_page":6,"total":12,"total_pages":2,"data":[{"id":1,"email":"[email protected]","first_name":"George","last_name":"Bluth","avatar":"https://reqres.in/img/faces/1-image.jpg"},{"id":2,"email":"[email protected]","first_name":"Janet","last_name":"Weaver","avatar":"https://reqres.in/img/faces/2-image.jpg"},{"id":3,"email":"[email protected]","first_name":"Emma","last_name":"Wong","avatar":"https://reqres.in/img/faces/3-image.jpg"},{"id":4,"email":"[email protected]","first_name":"Eve","last_name":"Holt","avatar":"https://reqres.in/img/faces/4-image.jpg"},{"id":5,"email":"[email protected]","first_name":"Charles","last_name":"Morris","avatar":"https://reqres.in/img/faces/5-image.jpg"},{"id":6,"email":"[email protected]","first_name":"Tracey","last_name":"Ramos","avatar":"https://reqres.in/img/faces/6-image.jpg"}],"support":{"url":"https://reqres.in/#support-heading","text":"To keep ReqRes free, contributions towards server costs are appreciated!"}} 2023-01-06 11:24:50,137 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e, L:/100.64.0.1:60737 - R:reqres.in/104.26.10.213:443] READ COMPLETE 2023-01-06 11:26:38,024 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e, L:/100.64.0.1:60737 - R:reqres.in/104.26.10.213:443] READ COMPLETE 2023-01-06 11:26:38,042 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e, L:/100.64.0.1:60737 ! R:reqres.in/104.26.10.213:443] USER_EVENT: SslCloseCompletionEvent(java.nio.channels.ClosedChannelException) 2023-01-06 11:26:38,043 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e, L:/100.64.0.1:60737 ! R:reqres.in/104.26.10.213:443] INACTIVE 2023-01-06 11:26:38,044 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [d91d128e, L:/100.64.0.1:60737 ! R:reqres.in/104.26.10.213:443] UNREGISTERED `
I just added logback-spring.xml to the repo above in resources folder -
<?xml version="1.0" encoding="UTF-8"?> <configuration> <appender name="Console" class="ch.qos.logback.core.ConsoleAppender"> <layout class="ch.qos.logback.classic.PatternLayout"> <pattern> %black(%d{ISO8601}) %highlight(%-5level) [%blue(%t)] [%blue(%mdc)] %yellow(%C): %msg%n%throwable </pattern> </layout> </appender> <root level="info"> <appender-ref ref="Console"/> </root> </configuration>
can you try with Spring Boot 2.x? I just tried and was able to see the correlation. I will look into why the correlation doesn't seem to be working with Spring Boot 3
Hi @trask
I tried with spring boot 2.x version as well but could see the same behaviour
` OpenJDK 64-Bit Server VM warning: Options -Xverify:none and -noverify were deprecated in JDK 13 and will likely be removed in a future release. OpenJDK 64-Bit Server VM warning: Sharing is only supported for boot loader classes because bootstrap classpath has been appended 2023-01-06 12:17:00.988+11:00 INFO c.m.applicationinsights.agent - Application Insights Java Agent 3.4.7 started successfully (PID 29588, JVM running for 7.706 s) 2023-01-06 12:17:00.993+11:00 INFO c.m.applicationinsights.agent - Java version: 17.0.2, vendor: Eclipse Adoptium, home: /Users/mjain9/.sdkman/candidates/java/17.0.2-tem
. ____ _ __ _ _
/\ / ' __ _ () __ __ _ \ \ \
( ( )__ | '_ | '| | ' / ` | \ \ \
\/ )| |)| | | | | || (| | ) ) ) )
' || .__|| ||| |_, | / / / /
=========||==============|/=////
:: Spring Boot :: (v2.7.0)
2023-01-06 12:17:01,879 INFO [main] [] org.springframework.boot.StartupInfoLogger: Starting NettywiretapApplication using Java 17.0.2 on CMC02DWBMLML7H with PID 29588 (/Users/mjain9/Desktop/worspace/nettywiretap/build/classes/java/main started by mjain9 in /Users/mjain9/Desktop/worspace/nettywiretap) 2023-01-06 12:17:01,891 INFO [main] [] org.springframework.boot.SpringApplication: No active profile set, falling back to 1 default profile: "default" 2023-01-06 12:17:03,071 INFO [main] [] org.springframework.boot.web.embedded.tomcat.TomcatWebServer: Tomcat initialized with port(s): 8080 (http) 2023-01-06 12:17:03,101 INFO [main] [] org.apache.juli.logging.DirectJDKLog: Initializing ProtocolHandler ["http-nio-8080"] 2023-01-06 12:17:03,101 INFO [main] [] org.apache.juli.logging.DirectJDKLog: Starting service [Tomcat] 2023-01-06 12:17:03,102 INFO [main] [] org.apache.juli.logging.DirectJDKLog: Starting Servlet engine: [Apache Tomcat/9.0.63] 2023-01-06 12:17:03,208 INFO [main] [] org.apache.juli.logging.DirectJDKLog: Initializing Spring embedded WebApplicationContext 2023-01-06 12:17:03,208 INFO [main] [] org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext: Root WebApplicationContext: initialization completed in 1280 ms 2023-01-06 12:17:04,515 INFO [main] [] org.apache.juli.logging.DirectJDKLog: Starting ProtocolHandler ["http-nio-8080"] 2023-01-06 12:17:04,549 INFO [main] [] org.springframework.boot.web.embedded.tomcat.TomcatWebServer: Tomcat started on port(s): 8080 (http) with context path '' 2023-01-06 12:17:04,561 INFO [main] [] org.springframework.boot.StartupInfoLogger: Started NettywiretapApplication in 3.109 seconds (JVM running for 11.281) 2023-01-06 12:17:24,890 INFO [http-nio-8080-exec-1] [trace_id=7ef7aac385eccf5eea59891b0f9f6765, trace_flags=01, span_id=d01a5469c4bed89c] org.apache.juli.logging.DirectJDKLog: Initializing Spring DispatcherServlet 'dispatcherServlet' 2023-01-06 12:17:24,891 INFO [http-nio-8080-exec-1] [trace_id=7ef7aac385eccf5eea59891b0f9f6765, trace_flags=01, span_id=d01a5469c4bed89c] org.springframework.web.servlet.FrameworkServlet: Initializing Servlet 'dispatcherServlet' 2023-01-06 12:17:24,893 INFO [http-nio-8080-exec-1] [trace_id=7ef7aac385eccf5eea59891b0f9f6765, trace_flags=01, span_id=d01a5469c4bed89c] org.springframework.web.servlet.FrameworkServlet: Completed initialization in 2 ms 2023-01-06 12:17:25,095 TRACE [http-nio-8080-exec-1] [trace_id=7ef7aac385eccf5eea59891b0f9f6765, trace_flags=01, span_id=d01a5469c4bed89c] org.zalando.logbook.DefaultHttpLogWriter: {"origin":"remote","type":"request","correlation":"968db314201f0903","protocol":"HTTP/1.1","remote":"127.0.0.1","method":"GET","uri":"http://localhost:8080/users","host":"localhost","path":"/users","scheme":"http","port":"8080","headers":{"accept-encoding":["gzip,deflate"],"connection":["Keep-Alive"],"host":["localhost:8080"],"user-agent":["Apache-HttpClient/4.5.13 (Java/11.0.13)"]}} 2023-01-06 12:17:25,128 INFO [http-nio-8080-exec-1] [trace_id=7ef7aac385eccf5eea59891b0f9f6765, trace_flags=01, span_id=d01a5469c4bed89c] com.example.nettywiretap.controller.SampleController: Getting User list with details! 2023-01-06 12:17:28,894 DEBUG [reactor-http-nio-3] [trace_id=7ef7aac385eccf5eea59891b0f9f6765, trace_flags=01, span_id=73510c52a16a5155] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3] REGISTERED 2023-01-06 12:17:29,052 DEBUG [reactor-http-nio-3] [trace_id=7ef7aac385eccf5eea59891b0f9f6765, trace_flags=01, span_id=73510c52a16a5155] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3] CONNECT: reqres.in/104.26.11.213:443 2023-01-06 12:17:29,092 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3, L:/100.64.0.1:62512 - R:reqres.in/104.26.11.213:443] ACTIVE 2023-01-06 12:17:29,142 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3, L:/100.64.0.1:62512 - R:reqres.in/104.26.11.213:443] READ COMPLETE 2023-01-06 12:17:29,153 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3, L:/100.64.0.1:62512 - R:reqres.in/104.26.11.213:443] USER_EVENT: SslHandshakeCompletionEvent(SUCCESS) 2023-01-06 12:17:29,237 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3-1, L:/100.64.0.1:62512 - R:reqres.in/104.26.11.213:443] WRITE: 160B GET /api/users HTTP/1.1 user-agent: ReactorNetty/1.0.19 host: reqres.in accept: / traceparent: 00-7ef7aac385eccf5eea59891b0f9f6765-73510c52a16a5155-01
2023-01-06 12:17:29,243 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3-1, L:/100.64.0.1:62512 - R:reqres.in/104.26.11.213:443] FLUSH 2023-01-06 12:17:29,258 TRACE [reactor-http-nio-3] [] org.zalando.logbook.DefaultHttpLogWriter: {"origin":"local","type":"request","correlation":"926a38a85066a09c","protocol":"HTTP/1.1","remote":"reqres.in/104.26.11.213:443","method":"GET","uri":"https://reqres.in/api/users","host":"reqres.in","path":"/api/users","scheme":"https","port":"443","headers":{"accept":["/"],"host":["reqres.in"],"traceparent":["00-7ef7aac385eccf5eea59891b0f9f6765-73510c52a16a5155-01"],"user-agent":["ReactorNetty/1.0.19"]}} 2023-01-06 12:17:29,258 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3-1, L:/100.64.0.1:62512 - R:reqres.in/104.26.11.213:443] WRITE: 0B 2023-01-06 12:17:29,259 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3-1, L:/100.64.0.1:62512 - R:reqres.in/104.26.11.213:443] FLUSH 2023-01-06 12:17:29,260 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3-1, L:/100.64.0.1:62512 - R:reqres.in/104.26.11.213:443] READ COMPLETE 2023-01-06 12:17:29,285 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3-1, L:/100.64.0.1:62512 - R:reqres.in/104.26.11.213:443] READ: 1714B HTTP/1.1 200 OK Date: Fri, 06 Jan 2023 01:17:29 GMT Content-Type: application/json; charset=utf-8 Content-Length: 996 Connection: keep-alive X-Powered-By: Express Access-Control-Allow-Origin: * Etag: W/"3e4-2RLXvr5wTg9YQ6aH95CkYoFNuO8" Via: 1.1 vegur Cache-Control: max-age=14400 CF-Cache-Status: HIT Age: 2226 Accept-Ranges: bytes Report-To: {"endpoints":[{"url":"https://a.nel.cloudflare.com/report/v3?s=MMA%2BUb1mVt74iahbpUyEbUgIfTLY35dhiXOTmdxYMCaolCpnO33n4TL05FZ8tVkDiyt77Mw%2Bsxw60%2FUSafFPK747iHC4iyaZMdI37v%2BUXvYcdGLoIluQ1SnoPw%3D%3D"}],"group":"cf-nel","max_age":604800} NEL: {"success_fraction":0,"report_to":"cf-nel","max_age":604800} Server: cloudflare CF-RAY: 78509d428d8629a8-MEL
{"page":1,"per_page":6,"total":12,"total_pages":2,"data":[{"id":1,"email":"[email protected]","first_name":"George","last_name":"Bluth","avatar":"https://reqres.in/img/faces/1-image.jpg"},{"id":2,"email":"[email protected]","first_name":"Janet","last_name":"Weaver","avatar":"https://reqres.in/img/faces/2-image.jpg"},{"id":3,"email":"[email protected]","first_name":"Emma","last_name":"Wong","avatar":"https://reqres.in/img/faces/3-image.jpg"},{"id":4,"email":"[email protected]","first_name":"Eve","last_name":"Holt","avatar":"https://reqres.in/img/faces/4-image.jpg"},{"id":5,"email":"[email protected]","first_name":"Charles","last_name":"Morris","avatar":"https://reqres.in/img/faces/5-image.jpg"},{"id":6,"email":"[email protected]","first_name":"Tracey","last_name":"Ramos","avatar":"https://reqres.in/img/faces/6-image.jpg"}],"support":{"url":"https://reqres.in/#support-heading","text":"To keep ReqRes free, contributions towards server costs are appreciated!"}} 2023-01-06 12:17:29,405 TRACE [reactor-http-nio-3] [] org.zalando.logbook.DefaultHttpLogWriter: {"origin":"remote","type":"response","correlation":"926a38a85066a09c","duration":163,"protocol":"HTTP/1.1","status":200,"headers":{"Accept-Ranges":["bytes"],"Access-Control-Allow-Origin":["*"],"Age":["2226"],"Cache-Control":["max-age=14400"],"CF-Cache-Status":["HIT"],"CF-RAY":["78509d428d8629a8-MEL"],"Connection":["keep-alive"],"content-length":["996"],"Content-Type":["application/json; charset=utf-8"],"Date":["Fri, 06 Jan 2023 01:17:29 GMT"],"Etag":["W/"3e4-2RLXvr5wTg9YQ6aH95CkYoFNuO8""],"NEL":["{"success_fraction":0,"report_to":"cf-nel","max_age":604800}"],"Report-To":["{"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=MMA%2BUb1mVt74iahbpUyEbUgIfTLY35dhiXOTmdxYMCaolCpnO33n4TL05FZ8tVkDiyt77Mw%2Bsxw60%2FUSafFPK747iHC4iyaZMdI37v%2BUXvYcdGLoIluQ1SnoPw%3D%3D"}],"group":"cf-nel","max_age":604800}"],"Server":["cloudflare"],"Via":["1.1 vegur"],"X-Powered-By":["Express"]},"body":{"page":1,"per_page":6,"total":12,"total_pages":2,"data":[{"id":1,"email":"[email protected]","first_name":"George","last_name":"Bluth","avatar":"https://reqres.in/img/faces/1-image.jpg"},{"id":2,"email":"[email protected]","first_name":"Janet","last_name":"Weaver","avatar":"https://reqres.in/img/faces/2-image.jpg"},{"id":3,"email":"[email protected]","first_name":"Emma","last_name":"Wong","avatar":"https://reqres.in/img/faces/3-image.jpg"},{"id":4,"email":"[email protected]","first_name":"Eve","last_name":"Holt","avatar":"https://reqres.in/img/faces/4-image.jpg"},{"id":5,"email":"[email protected]","first_name":"Charles","last_name":"Morris","avatar":"https://reqres.in/img/faces/5-image.jpg"},{"id":6,"email":"[email protected]","first_name":"Tracey","last_name":"Ramos","avatar":"https://reqres.in/img/faces/6-image.jpg"}],"support":{"url":"https://reqres.in/#support-heading","text":"To keep ReqRes free, contributions towards server costs are appreciated!"}}} 2023-01-06 12:17:29,431 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3, L:/100.64.0.1:62512 - R:reqres.in/104.26.11.213:443] READ COMPLETE 2023-01-06 12:17:29,467 TRACE [http-nio-8080-exec-2] [trace_id=7ef7aac385eccf5eea59891b0f9f6765, trace_flags=01, span_id=d01a5469c4bed89c] org.zalando.logbook.DefaultHttpLogWriter: {"origin":"local","type":"response","correlation":"968db314201f0903","duration":4536,"protocol":"HTTP/1.1","status":200,"headers":{"Connection":["keep-alive"],"Content-Type":["application/json"],"Date":["Fri, 06 Jan 2023 01:17:29 GMT"],"Keep-Alive":["timeout=60"],"Transfer-Encoding":["chunked"]},"body":{"page":1,"total":12,"data":[{"id":1,"email":"[email protected]","avatar":"https://reqres.in/img/faces/1-image.jpg","first_name":"George","last_name":"Bluth"},{"id":2,"email":"[email protected]","avatar":"https://reqres.in/img/faces/2-image.jpg","first_name":"Janet","last_name":"Weaver"},{"id":3,"email":"[email protected]","avatar":"https://reqres.in/img/faces/3-image.jpg","first_name":"Emma","last_name":"Wong"},{"id":4,"email":"[email protected]","avatar":"https://reqres.in/img/faces/4-image.jpg","first_name":"Eve","last_name":"Holt"},{"id":5,"email":"[email protected]","avatar":"https://reqres.in/img/faces/5-image.jpg","first_name":"Charles","last_name":"Morris"},{"id":6,"email":"[email protected]","avatar":"https://reqres.in/img/faces/6-image.jpg","first_name":"Tracey","last_name":"Ramos"}],"per_page":6,"total_pages":2}} 2023-01-06 12:19:17,304 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3, L:/100.64.0.1:62512 - R:reqres.in/104.26.11.213:443] READ COMPLETE 2023-01-06 12:19:17,323 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3, L:/100.64.0.1:62512 ! R:reqres.in/104.26.11.213:443] USER_EVENT: SslCloseCompletionEvent(java.nio.channels.ClosedChannelException) 2023-01-06 12:19:17,324 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3, L:/100.64.0.1:62512 ! R:reqres.in/104.26.11.213:443] INACTIVE 2023-01-06 12:19:17,324 DEBUG [reactor-http-nio-3] [] io.netty.util.internal.logging.AbstractInternalLogger: [570d64c3, L:/100.64.0.1:62512 ! R:reqres.in/104.26.11.213:443] UNREGISTERED `

thanks @mohitj13! I understand and am able to repro now. We will investigate.
Any update on this? We might have the issue over here...
Can't get MDC properties to show up in App Insights. Ugh!
Thanks!
hi @mikeliucc! I was able to isolate @mohitj13's issue to a context propagation issue when using netty's LoggingHandler
can you open a new issue, and let us know which logging library you're using, and ideally a small repro or sample code so we can better understand the issue you're having?
Thanks for replying, @trask !
Unfortunately we have a fairly large project.. not easy to break it into small demo repo.
But I can tell you about our stack and some snippets under a new issue (will tag you). Thanks!
Any updates on this? I'm facing the same issue, wiretapped logs are not correlated to the rest of the logs.