gRPC logging
Sample gRPC logs from kas:
{"level":"debug","time":"2022-06-10T19:49:03.011+1000","msg":"Initializing Sentry error tracking","sentry_dsn":"","sentry_env":""}
{"level":"info","time":"2022-06-10T19:49:03.011+1000","msg":"[core] [Server #1] Server created"}
{"level":"info","time":"2022-06-10T19:49:03.012+1000","msg":"[core] [Server #2] Server created"}
{"level":"info","time":"2022-06-10T19:49:03.012+1000","msg":"[core] [Server #3] Server created"}
{"level":"info","time":"2022-06-10T19:49:03.012+1000","msg":"[core] [Channel #4] Channel created"}
{"level":"info","time":"2022-06-10T19:49:03.012+1000","msg":"[core] [Channel #4] original dial target is: \"pipe\""}
{"level":"info","time":"2022-06-10T19:49:03.012+1000","msg":"[core] [Channel #4] parsed dial target is: {Scheme: Authority: Endpoint:pipe URL:{Scheme: Opaque: User: Host: Path:pipe RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}"}
{"level":"info","time":"2022-06-10T19:49:03.012+1000","msg":"[core] [Channel #4] fallback to scheme \"passthrough\""}
{"level":"info","time":"2022-06-10T19:49:03.012+1000","msg":"[core] [Channel #4] parsed dial target is: {Scheme:passthrough Authority: Endpoint:pipe URL:{Scheme:passthrough Opaque: User: Host: Path:/pipe RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}"}
{"level":"info","time":"2022-06-10T19:49:03.012+1000","msg":"[core] [Channel #4] Channel authority set to \"pipe\""}
{"level":"info","time":"2022-06-10T19:49:03.012+1000","msg":"[core] [Channel #4] Resolver state updated: {\n \"Addresses\": [\n {\n \"Addr\": \"pipe\",\n \"ServerName\": \"\",\n \"Attributes\": null,\n \"BalancerAttributes\": null,\n \"Type\": 0,\n \"Metadata\": null\n }\n ],\n \"ServiceConfig\": null,\n \"Attributes\": null\n} (resolver returned new addresses)"}
{"level":"info","time":"2022-06-10T19:49:03.012+1000","msg":"[core] [Channel #4] Channel switches to new LB policy \"pick_first\""}
{"level":"info","time":"2022-06-10T19:49:03.013+1000","msg":"[core] [Channel #4 SubChannel #5] Subchannel created"}
{"level":"info","time":"2022-06-10T19:49:03.013+1000","msg":"[core] [Channel #4 SubChannel #5] Subchannel Connectivity change to CONNECTING"}
{"level":"info","time":"2022-06-10T19:49:03.013+1000","msg":"[core] [Channel #4 SubChannel #5] Subchannel picks a new address \"pipe\" to connect"}
{"level":"info","time":"2022-06-10T19:49:03.013+1000","msg":"[core] pickfirstBalancer: UpdateSubConnState: 0xc00019abf0, {CONNECTING <nil>}"}
{"level":"info","time":"2022-06-10T19:49:03.013+1000","msg":"[core] [Channel #4] Channel Connectivity change to CONNECTING"}
{"level":"info","time":"2022-06-10T19:49:03.014+1000","msg":"[core] [Server #6] Server created"}
{"level":"info","time":"2022-06-10T19:49:03.016+1000","msg":"Observability endpoint is up","mod_name":"observability","net_network":"tcp","net_address":"127.0.0.1:8151"}
{"level":"info","time":"2022-06-10T19:49:03.016+1000","msg":"Kubernetes API endpoint is up","mod_name":"kubernetes_api","net_network":"tcp","net_address":"172.16.123.1:8154"}
{"level":"info","time":"2022-06-10T19:49:03.017+1000","msg":"API endpoint is up","net_network":"tcp","net_address":"172.16.123.1:8153"}
{"level":"info","time":"2022-06-10T19:49:03.017+1000","msg":"[core] [Server #6 ListenSocket #7] ListenSocket created"}
{"level":"info","time":"2022-06-10T19:49:03.017+1000","msg":"Private API endpoint is up","net_network":"tcp","net_address":"172.16.123.1:8155"}
{"level":"info","time":"2022-06-10T19:49:03.017+1000","msg":"[core] [Server #2 ListenSocket #8] ListenSocket created"}
{"level":"info","time":"2022-06-10T19:49:03.017+1000","msg":"Agentk API endpoint is up","net_network":"tcp","net_address":"172.16.123.1:8159","is_websocket":true}
{"level":"info","time":"2022-06-10T19:49:03.017+1000","msg":"[core] [Server #3 ListenSocket #9] ListenSocket created"}
{"level":"info","time":"2022-06-10T19:49:03.018+1000","msg":"[core] [Server #1 ListenSocket #10] ListenSocket created"}
{"level":"info","time":"2022-06-10T19:49:03.018+1000","msg":"[core] CPU time info is unavailable on non-linux environments."}
{"level":"info","time":"2022-06-10T19:49:03.018+1000","msg":"[core] [Channel #4 SubChannel #5] Subchannel Connectivity change to READY"}
{"level":"info","time":"2022-06-10T19:49:03.018+1000","msg":"[core] pickfirstBalancer: UpdateSubConnState: 0xc00019abf0, {READY <nil>}"}
{"level":"info","time":"2022-06-10T19:49:03.018+1000","msg":"[core] [Channel #4] Channel Connectivity change to READY"}
{"level":"info","time":"2022-06-10T19:49:21.567+1000","msg":"[core] [Channel #14] Channel created"}
{"level":"info","time":"2022-06-10T19:49:21.567+1000","msg":"[core] [Channel #14] original dial target is: \"unix:/Users/mike/src/gdk/praefect.socket\""}
{"level":"info","time":"2022-06-10T19:49:21.567+1000","msg":"[core] [Channel #14] parsed dial target is: {Scheme:unix Authority: Endpoint:Users/mike/src/gdk/praefect.socket URL:{Scheme:unix Opaque: User: Host: Path:/Users/mike/src/gdk/praefect.socket RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}"}
{"level":"info","time":"2022-06-10T19:49:21.567+1000","msg":"[core] [Channel #14] Channel authority set to \"localhost\""}
{"level":"info","time":"2022-06-10T19:49:21.567+1000","msg":"[core] [Channel #14] Resolver state updated: {\n \"Addresses\": [\n {\n \"Addr\": \"/Users/mike/src/gdk/praefect.socket\",\n \"ServerName\": \"\",\n \"Attributes\": {},\n \"BalancerAttributes\": null,\n \"Type\": 0,\n \"Metadata\": null\n }\n ],\n \"ServiceConfig\": null,\n \"Attributes\": null\n} (resolver returned new addresses)"}
{"level":"info","time":"2022-06-10T19:49:21.567+1000","msg":"[core] [Channel #14] Channel switches to new LB policy \"pick_first\""}
{"level":"info","time":"2022-06-10T19:49:21.567+1000","msg":"[core] [Channel #14 SubChannel #15] Subchannel created"}
{"level":"info","time":"2022-06-10T19:49:21.568+1000","msg":"[core] [Channel #14 SubChannel #15] Subchannel Connectivity change to CONNECTING"}
{"level":"info","time":"2022-06-10T19:49:21.568+1000","msg":"[core] [Channel #14 SubChannel #15] Subchannel picks a new address \"/Users/mike/src/gdk/praefect.socket\" to connect"}
{"level":"info","time":"2022-06-10T19:49:21.568+1000","msg":"[core] pickfirstBalancer: UpdateSubConnState: 0xc000692850, {CONNECTING <nil>}"}
{"level":"info","time":"2022-06-10T19:49:21.568+1000","msg":"[core] [Channel #14] Channel Connectivity change to CONNECTING"}
{"level":"info","time":"2022-06-10T19:49:21.568+1000","msg":"[core] blockingPicker: the picked transport is not ready, loop back to repick"}
{"level":"info","time":"2022-06-10T19:49:21.568+1000","msg":"[core] [Channel #14 SubChannel #15] Subchannel Connectivity change to READY"}
{"level":"info","time":"2022-06-10T19:49:21.568+1000","msg":"[core] pickfirstBalancer: UpdateSubConnState: 0xc000692850, {READY <nil>}"}
{"level":"info","time":"2022-06-10T19:49:21.568+1000","msg":"[core] [Channel #14] Channel Connectivity change to READY"}Sample gRPC logs from agentk:
{"level":"info","time":"2022-06-10T19:49:19.031+1000","msg":"Observability endpoint is up","mod_name":"observability","net_network":"tcp","net_address":"[::]:8080"}
{"level":"info","time":"2022-06-10T19:49:44.655+1000","msg":"[core] [Channel #1 SubChannel #2] Subchannel Connectivity change to IDLE"}
{"level":"info","time":"2022-06-10T19:49:44.655+1000","msg":"[core] blockingPicker: the picked transport is not ready, loop back to repick"}
{"level":"info","time":"2022-06-10T19:49:44.655+1000","msg":"[core] blockingPicker: the picked transport is not ready, loop back to repick"}
{"level":"info","time":"2022-06-10T19:49:44.655+1000","msg":"[core] pickfirstBalancer: UpdateSubConnState: 0xc000631ed0, {IDLE <nil>}"}
{"level":"info","time":"2022-06-10T19:49:44.655+1000","msg":"[core] [Channel #1] Channel Connectivity change to IDLE"}
{"level":"info","time":"2022-06-10T19:49:44.655+1000","msg":"[transport] transport: loopyWriter.run returning. connection error: desc = \"transport is closing\""}
{"level":"info","time":"2022-06-10T19:49:44.655+1000","msg":"[core] [Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING"}
{"level":"info","time":"2022-06-10T19:49:44.656+1000","msg":"[core] [Channel #1 SubChannel #2] Subchannel picks a new address \"wss://gdk.test:3443/-/kubernetes-agent\" to connect"}
{"level":"info","time":"2022-06-10T19:49:44.656+1000","msg":"[core] pickfirstBalancer: UpdateSubConnState: 0xc000631ed0, {CONNECTING <nil>}"}
{"level":"info","time":"2022-06-10T19:49:44.656+1000","msg":"[core] [Channel #1] Channel Connectivity change to CONNECTING"}
{"level":"warn","time":"2022-06-10T19:49:44.670+1000","msg":"[core] [Channel #1 SubChannel #2] grpc: addrConn.createTransport failed to connect to {\n \"Addr\": \"wss://gdk.test:3443/-/kubernetes-agent\",\n \"ServerName\": \"wss://gdk.test:3443/-/kubernetes-agent\",\n \"Attributes\": null,\n \"BalancerAttributes\": null,\n \"Type\": 0,\n \"Metadata\": null\n}. Err: connection error: desc = \"transport: Error while dialing failed to WebSocket dial: expected handshake response status code 101 but got 502\""}
{"level":"info","time":"2022-06-10T19:49:44.670+1000","msg":"[core] [Channel #1 SubChannel #2] Subchannel Connectivity change to TRANSIENT_FAILURE"}
{"level":"info","time":"2022-06-10T19:49:44.670+1000","msg":"[core] pickfirstBalancer: UpdateSubConnState: 0xc000631ed0, {TRANSIENT_FAILURE connection error: desc = \"transport: Error while dialing failed to WebSocket dial: expected handshake response status code 101 but got 502\"}"}
{"level":"info","time":"2022-06-10T19:49:44.670+1000","msg":"[core] [Channel #1] Channel Connectivity change to TRANSIENT_FAILURE"}
{"level":"warn","time":"2022-06-10T19:49:44.670+1000","msg":"GetConfiguration failed","error":"rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing failed to WebSocket dial: expected handshake response status code 101 but got 502\""}
{"level":"error","time":"2022-06-10T19:49:44.670+1000","msg":"Error handling a connection","mod_name":"reverse_tunnel","error":"Connect(): rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing failed to WebSocket dial: expected handshake response status code 101 but got 502\""}
{"level":"error","time":"2022-06-10T19:49:44.670+1000","msg":"Error handling a connection","mod_name":"reverse_tunnel","error":"Connect(): rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing failed to WebSocket dial: expected handshake response status code 101 but got 502\""}
{"level":"info","time":"2022-06-10T19:49:45.671+1000","msg":"[core] [Channel #1 SubChannel #2] Subchannel Connectivity change to IDLE"}
{"level":"info","time":"2022-06-10T19:49:45.671+1000","msg":"[core] pickfirstBalancer: UpdateSubConnState: 0xc000631ed0, {IDLE connection error: desc = \"transport: Error while dialing failed to WebSocket dial: expected handshake response status code 101 but got 502\"}"}
{"level":"info","time":"2022-06-10T19:49:45.671+1000","msg":"[core] [Channel #1] Channel Connectivity change to IDLE"}Relates to #255 (closed). This MR should help debug networking issues.
Edited by Mikhail Mazurskiy