microsoft / ApplicationInsights-Java

Application Insights for Java
http://aka.ms/application-insights
Other
296 stars 199 forks source link

Reactor Netty HttpClient Wiretap Logs missing from tracing #2730

Open mohitj13 opened 1 year ago

mohitj13 commented 1 year ago

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:

trask commented 1 year ago

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

mohitj13 commented 1 year ago

@trask YES the Java logging threshold is set to DEBUG level

trask commented 1 year ago

did you set it using APPLICATIONINSIGHTS_INSTRUMENTATION_LOGGING_LEVEL=DEBUG or using below?

{
  "instrumentation": {
    "logging": {
      "level": "DEBUG"
    }
  }
}
mohitj13 commented 1 year ago

I have actually tried both to be honest. For now I am using - { "instrumentation": { "logging": { "level": "DEBUG" } } }

trask commented 1 year ago

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!

ghost commented 1 year ago

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.

mohitj13 commented 1 year ago

Hi @trask

Apologies for this delay, please find the attached source replicated that is failing to track the logs to appinsights nettywiretap.zip

trask commented 1 year ago

@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\":\"george.bluth@reqres.in\",\"first_name\":\"George\",\"last_name\":\"Bluth\",\"avatar\":\"https://reqres.in/img/faces/1-image.jpg\"},{\"id\":2,\"email\":\"janet.weaver@reqres.in\",\"first_name\":\"Janet\",\"last_name\":\"Weaver\",\"avatar\":\"https://reqres.in/img/faces/2-image.jpg\"},{\"id\":3,\"email\":\"emma.wong@reqres.in\",\"first_name\":\"Emma\",\"last_name\":\"Wong\",\"avatar\":\"https://reqres.in/img/faces/3-image.jpg\"},{\"id\":4,\"email\":\"eve.holt@reqres.in\",\"first_name\":\"Eve\",\"last_name\":\"Holt\",\"avatar\":\"https://reqres.in/img/faces/4-image.jpg\"},{\"id\":5,\"email\":\"charles.morris@reqres.in\",\"first_name\":\"Charle","severityLevel":"Verbose","properties":{"LoggerName":"reactor.netty.http.client.HttpClient","SourceType":"Logger","ThreadName":"reactor-http-nio-3"}}}}

mohitj13 commented 1 year ago

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

Screen Shot 2023-01-06 at 10 40 20 am

AS we can see above in screenshot the above traces are not captured in the operation specific trace!

mohitj13 commented 1 year ago

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":"george.bluth@reqres.in","first_name":"George","last_name":"Bluth","avatar":"https://reqres.in/img/faces/1-image.jpg"},{"id":2,"email":"janet.weaver@reqres.in","first_name":"Janet","last_name":"Weaver","avatar":"https://reqres.in/img/faces/2-image.jpg"},{"id":3,"email":"emma.wong@reqres.in","first_name":"Emma","last_name":"Wong","avatar":"https://reqres.in/img/faces/3-image.jpg"},{"id":4,"email":"eve.holt@reqres.in","first_name":"Eve","last_name":"Holt","avatar":"https://reqres.in/img/faces/4-image.jpg"},{"id":5,"email":"charles.morris@reqres.in","first_name":"Charles","last_name":"Morris","avatar":"https://reqres.in/img/faces/5-image.jpg"},{"id":6,"email":"tracey.ramos@reqres.in","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"?>

%black(%d{ISO8601}) %highlight(%-5level) [%blue(%t)] [%blue(%mdc)] %yellow(%C): %msg%n%throwable `
trask commented 1 year ago

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

mohitj13 commented 1 year ago

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":"george.bluth@reqres.in","first_name":"George","last_name":"Bluth","avatar":"https://reqres.in/img/faces/1-image.jpg"},{"id":2,"email":"janet.weaver@reqres.in","first_name":"Janet","last_name":"Weaver","avatar":"https://reqres.in/img/faces/2-image.jpg"},{"id":3,"email":"emma.wong@reqres.in","first_name":"Emma","last_name":"Wong","avatar":"https://reqres.in/img/faces/3-image.jpg"},{"id":4,"email":"eve.holt@reqres.in","first_name":"Eve","last_name":"Holt","avatar":"https://reqres.in/img/faces/4-image.jpg"},{"id":5,"email":"charles.morris@reqres.in","first_name":"Charles","last_name":"Morris","avatar":"https://reqres.in/img/faces/5-image.jpg"},{"id":6,"email":"tracey.ramos@reqres.in","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":"george.bluth@reqres.in","first_name":"George","last_name":"Bluth","avatar":"https://reqres.in/img/faces/1-image.jpg"},{"id":2,"email":"janet.weaver@reqres.in","first_name":"Janet","last_name":"Weaver","avatar":"https://reqres.in/img/faces/2-image.jpg"},{"id":3,"email":"emma.wong@reqres.in","first_name":"Emma","last_name":"Wong","avatar":"https://reqres.in/img/faces/3-image.jpg"},{"id":4,"email":"eve.holt@reqres.in","first_name":"Eve","last_name":"Holt","avatar":"https://reqres.in/img/faces/4-image.jpg"},{"id":5,"email":"charles.morris@reqres.in","first_name":"Charles","last_name":"Morris","avatar":"https://reqres.in/img/faces/5-image.jpg"},{"id":6,"email":"tracey.ramos@reqres.in","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":"george.bluth@reqres.in","avatar":"https://reqres.in/img/faces/1-image.jpg","first_name":"George","last_name":"Bluth"},{"id":2,"email":"janet.weaver@reqres.in","avatar":"https://reqres.in/img/faces/2-image.jpg","first_name":"Janet","last_name":"Weaver"},{"id":3,"email":"emma.wong@reqres.in","avatar":"https://reqres.in/img/faces/3-image.jpg","first_name":"Emma","last_name":"Wong"},{"id":4,"email":"eve.holt@reqres.in","avatar":"https://reqres.in/img/faces/4-image.jpg","first_name":"Eve","last_name":"Holt"},{"id":5,"email":"charles.morris@reqres.in","avatar":"https://reqres.in/img/faces/5-image.jpg","first_name":"Charles","last_name":"Morris"},{"id":6,"email":"tracey.ramos@reqres.in","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 `

Screen Shot 2023-01-06 at 12 19 49 pm

nettywiretap.zip

trask commented 1 year ago

thanks @mohitj13! I understand and am able to repro now. We will investigate.

mikeliucc commented 1 year ago

Any update on this? We might have the issue over here...

Can't get MDC properties to show up in App Insights. Ugh!

Thanks!

trask commented 1 year ago

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?

mikeliucc commented 1 year ago

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!

karthika-kk commented 1 year ago

Any updates on this? I'm facing the same issue, wiretapped logs are not correlated to the rest of the logs.

Yith1 commented 1 month ago

I am also seeing this problem.