grpc-swift icon indicating copy to clipboard operation
grpc-swift copied to clipboard

Published 20 hours ago • verified publisher icon grpc

Is there a way to reduce the logs produced by the logger?

Open konekoya opened this issue 3 years ago • 2 comments

What are you trying to achieve?

I'm trying to print out some debug info about gRPC calls. This is what I normally do when debugging an HTTP request. Usually, with a browser's dev tools, you can obtain loads of information about your request/response like header, server IP and status. But it seems like it's not the case in the gRPC? I've configured my iOS following the docs. And tried out all log levels. There were only two log levels that worked for me: debug and trace, others simply not printing out anything. debug didn't produce helpful info while I was testing it. But on the other hand, trace level did produce some helpful debugging info like headers and call name and path, etc. One issue I found though -- it produced too many logs in my Xcode console.

So my question is how or is it possible to reduce or customize the logger level so I won't receive too many logs in my console?

What have you tried so far?

See the above description. An example for a simple get request that produces many logs in my console:

2021-12-17T16:07:07+0800 debug com.example.app CallOptions : call_state=awaitingTransport (0 parts buffered) grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 request_part=metadata buffering request part 2021-12-17T16:07:07+0800 debug com.example.app CallOptions : request_part=message grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 call_state=awaitingTransport (1 parts buffered) buffering request part 2021-12-17T16:07:07+0800 debug com.example.app CallOptions : call_state=awaitingTransport (2 parts buffered) grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 request_part=end buffering request part 2021-12-17T16:07:07+0800 debug com.example.app CallOptions : grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 activated stream channel 2021-12-17T16:07:07+0800 debug com.example.app CallOptions : request_parts=3 grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 unbuffering request parts 2021-12-17T16:07:07+0800 debug com.example.app CallOptions : request_part=metadata grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 unbuffering request part 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_payload=HEADERS h2_headers=[([], ":method", "POST"), ([], ":path", "/example.api.ExampleService/GetExample"), ([], ":authority", "10.1.13.102"), ([], ":scheme", "http"), ([], "content-type", "application/grpc"), ([], "te", "trailers"), ([], "authorization", "Bearer eyJ0eXAdsfsdfdsfsdJ9.eyJzdWIiOiJBRDQxRDlGQjQxsdfsfSIsImV4cCI6MTYzOTgsddsfzI4NDI1fQ.GNm0YiuAMpMSxsdfdsfeD4pAPZJfsdfds8"), ([], "user-agent", "grpc-swift-nio/1.0.0")] grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA writing HTTP2 frame 2021-12-17T16:07:07+0800 debug com.example.app CallOptions : request_part=message grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 unbuffering request part 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_data_bytes=5 h2_payload=DATA grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA writing HTTP2 frame 2021-12-17T16:07:07+0800 debug com.example.app CallOptions : request_part=end grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 unbuffering request part 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_data_bytes=0 h2_payload=DATA grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA h2_end_stream=true writing HTTP2 frame 2021-12-17T16:07:07+0800 debug com.example.app CallOptions : grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 request buffer drained 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false h2_headers=[([], ":status", "200"), ([], "content-type", "application/grpc+proto"), ([], "content-length", "36794"), ([], "grpc-encoding", "identity"), ([], "date", "Fri, 17 Dec 2021 08:07:07 GMT"), ([], "server", "akka-http/10.2.6")] grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_payload=HEADERS received HTTP2 frame 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false h2_data_bytes=924 grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_payload=DATA received HTTP2 frame 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false h2_data_bytes=2048 grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_payload=DATA received HTTP2 frame 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false h2_data_bytes=4096 grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_payload=DATA received HTTP2 frame 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false h2_data_bytes=163 grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_payload=DATA received HTTP2 frame 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false h2_data_bytes=8192 grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_payload=DATA received HTTP2 frame 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false h2_data_bytes=961 grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_payload=DATA received HTTP2 frame 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false h2_data_bytes=8214 grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_payload=DATA received HTTP2 frame 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false h2_data_bytes=8170 grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_payload=DATA received HTTP2 frame 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false h2_data_bytes=509 grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_payload=DATA received HTTP2 frame 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_end_stream=false grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA h2_payload=DATA h2_data_bytes=3517 received HTTP2 frame 2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=true h2_headers=[([], "grpc-status", "0")] grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA h2_payload=HEADERS received HTTP2 frame

Thank you for the help 🙏

konekoya avatar Dec 17 '21 08:12 konekoya

There were only two log levels that worked for me: debug and trace, others simply not printing out anything.

That's intentional; libraries should generally log at debug and trace. info and above should be application level logging.

So my question is how or is it possible to reduce or customize the logger level so I won't receive too many logs in my console?

Beyond setting the log level on the logger you have very few options. You could build a log handler to filter logs by the file they were logged from and so on but I don't think that's a particularly useful solution.

Really the better solution would be for us to improve our logging, to that end:

  • What trace level logs did you find useful that you think should be debug?
  • What wasn't logged that would be useful to log?
  • What did you have in mind for customising the logger to make debugging easier?

glbrntt avatar Dec 17 '21 09:12 glbrntt

That's intentional; libraries should generally log at debug and trace. info and above should be application level logging.

Thank you for clearing that up. Are there any resources that I could learn more about this topic?

What trace level logs did you find useful that you think should be debug?

The following two logs. I think these two are request/response logs and It would be very helpful if we could include these two in the debug level since debug level is less noise.

2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_payload=HEADERS h2_headers=[([], ":method", "POST"), ([], ":path", "/example.api.ExampleService/GetExample"), ([], ":authority", "10.1.13.102"), ([], ":scheme", "http"), ([], "content-type", "application/grpc"), ([], "te", "trailers"), ([], "authorization", "Bearer eyJ0eXAdsfsdfdsfsdJ9.eyJzdWIiOiJBRDQxRDlGQjQxsdfsfSIsImV4cCI6MTYzOTgsddsfzI4NDI1fQ.GNm0YiuAMpMSxsdfdsfeD4pAPZJfsdfds8"), ([], "user-agent", "grpc-swift-nio/1.0.0")] grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA writing HTTP2 frame

2021-12-17T16:07:07+0800 trace com.example.app CallOptions : h2_end_stream=false h2_headers=[([], ":status", "200"), ([], "content-type", "application/grpc+proto"), ([], "content-length", "36794"), ([], "grpc-encoding", "identity"), ([], "date", "Fri, 17 Dec 2021 08:07:07 GMT"), ([], "server", "akka-http/10.2.6")] grpc_request_id=44F67A2B-88BA-4CBD-8148-FFBBDA03EBCA grpc_connection_id=DABF7D5B-43F8-43EC-AFF8-3D3848C919C8/0 h2_payload=HEADERS received HTTP2 frame

What wasn't logged that would be useful to log? What did you have in mind for customising the logger to make debugging easier?

I was thinking about response data but just realized that the data coming from the wire won't be readable without decoding in Swift. So no for now.

Thanks!

konekoya avatar Dec 20 '21 07:12 konekoya