Quieter signaling and module logs #393
Merged
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
benjirewis
commented
Nov 19, 2024
| @@ -39,7 +39,7 @@ type ManagedProcess interface { | |||
|
|
|||
| // NewManagedProcess returns a new, unstarted, from the given configuration. | |||
| func NewManagedProcess(config ProcessConfig, logger utils.ZapCompatibleLogger) ManagedProcess { | |||
| logger = utils.Sublogger(logger, fmt.Sprintf("process.%s_%s", config.ID, config.Name)) | |||
| logger = utils.Sublogger(logger, config.ID) | |||
There was a problem hiding this comment.
config.ID is the name of the module and config.Name is the path to the module executable per how we create the ProcessConfig in the module manager code. The change I have here changes logs like:
2024-11-19T15:17:06.065Z ERROR rdk.modmanager.process.SimpleModule_/home/benjirewis/Code/rdk/examples/customresources/demos/simplemodule/simplemodule.StdErr pexec/managed_process.go:275
\_ A message from the module to STDERR
2024-11-19T15:17:06.065Z INFO rdk.modmanager.process.SimpleModule_/home/benjirewis/Code/rdk/examples/customresources/demos/simplemodule/simplemodule.StdOut pexec/managed_process.go:277
\_ A message from the module to STDOUT
to
2024-11-19T15:10:04.491Z ERROR rdk.modmanager.SimpleModule.StdErr pexec/managed_process.go:275
\_ A message from the module to STDERR
2024-11-19T15:10:04.491Z INFO rdk.modmanager.SimpleModule.StdOut pexec/managed_process.go:277
\_ A message from the module to STDOUT
It's not perfect, but I find it much easier to read, and I do not think the process prefix or the executable path are useful.
There was a problem hiding this comment.
Agreed, removing the executable path is not helpful. Just leave a comment that the config.ID maps to the module name in the robot config.
| @@ -131,17 +131,23 @@ func newBaseChannel( | |||
| connIDMu.Lock() | |||
| connID = connInfo.ID | |||
| connIDMu.Unlock() | |||
| logger.Infow("Connection state changed", | |||
| connectionStateChangedLogFields := []interface{}{ | |||
There was a problem hiding this comment.
Changes to this file manifest as changing the four info-level logs:
2024-11-19T15:21:15.299Z INFO rdk.networking rpc/wrtc_base_channel.go:134 Connection state changed {"conn_id":"PeerConnection-1732029675298047560","conn_state":"new","conn_local_candidates":[{"FoundAt":"2024-11-19T15:21:15.299000064Z","CandType":"host","IP":"127.0.0.1"},{"FoundAt":"2024-11-19T15:21:15.299000064Z","CandType":"host","IP":"10.1.6.70"}],"conn_remote_candidates":null}
2024-11-19T15:21:15.299Z INFO rdk.networking rpc/wrtc_base_channel.go:134 Connection state changed {"conn_id":"PeerConnection-1732029675298047560","conn_state":"checking","conn_local_candidates":[{"FoundAt":"2024-11-19T15:21:15.299000064Z","CandType":"host","IP":"127.0.0.1"},{"FoundAt":"2024-11-19T15:21:15.299000064Z","CandType":"host","IP":"172.17.0.1"},{"FoundAt":"2024-11-19T15:21:15.299000064Z","CandType":"host","IP":"100.74.14.74"},{"FoundAt":"2024-11-19T15:21:15.299000064Z","CandType":"host","IP":"10.1.6.70"}],"conn_remote_candidates":null}
2024-11-19T15:21:15.344Z INFO rdk.networking rpc/wrtc_base_channel.go:134 Connection state changed {"conn_id":"PeerConnection-1732029675298047560","conn_state":"connected","conn_local_candidates":[{"FoundAt":"2024-11-19T15:21:15.344Z","CandType":"server-reflexive","IP":"71.167.222.112"},{"FoundAt":"2024-11-19T15:21:15.344Z","CandType":"host","IP":"127.0.0.1"},{"FoundAt":"2024-11-19T15:21:15.344Z","CandType":"host","IP":"172.17.0.1"},{"FoundAt":"2024-11-19T15:21:15.344Z","CandType":"host","IP":"10.1.6.70"},{"FoundAt":"2024-11-19T15:21:15.344Z","CandType":"host","IP":"100.74.14.74"}],"conn_remote_candidates":[{"FoundAt":"2024-11-19T15:21:15.344Z","CandType":"peer-reflexive","IP":"10.1.6.70"}]}
2024-11-19T15:21:15.345Z INFO rdk.networking rpc/wrtc_base_channel.go:141 Selected candidate pair {"conn_id":"PeerConnection-1732029675298047560","candidate_pair":"(local) udp4 host 10.1.6.70:38820 <-> (remote) udp4 prflx 10.1.6.70:53043 related :0"}
to
2024-11-19T15:07:56.165Z INFO rdk.networking rpc/wrtc_base_channel.go:144 Connection establishment succeeded {"conn_id":"PeerConnection-1732028876106823945","conn_local_candidates":[{"FoundAt":"2024-11-19T15:07:56.164999936Z","CandType":"host","IP":"127.0.0.1"},{"FoundAt":"2024-11-19T15:07:56.164999936Z","CandType":"server-reflexive","IP":"71.167.222.112"},{"FoundAt":"2024-11-19T15:07:56.164999936Z","CandType":"host","IP":"10.1.6.70"},{"FoundAt":"2024-11-19T15:07:56.164999936Z","CandType":"host","IP":"172.17.0.1"},{"FoundAt":"2024-11-19T15:07:56.164999936Z","CandType":"host","IP":"100.74.14.74"}],"conn_remote_candidates":[{"FoundAt":"2024-11-19T15:07:56.164999936Z","CandType":"peer-reflexive","IP":"10.1.6.70"}],"candidate_pair":"(local) udp4 host 10.1.6.70:34019 <-> (remote) udp4 prflx 10.1.6.70:49217 related :0"}
The first two are downgraded to debug-level and the latter two are combined into a single log.
| @@ -144,7 +144,8 @@ func checkExceptionalError(err error) error { | |||
| strings.Contains(s.Message(), "too_many_pings") || | |||
| // RSDK-3025: Cloud Run has a max one hour timeout which will terminate gRPC | |||
| // streams, but leave the underlying connection open. | |||
| strings.Contains(s.Message(), "upstream max stream duration reached"))) { | |||
| strings.Contains(s.Message(), "upstream max stream duration reached") || | |||
| strings.Contains(s.Message(), "server closed the stream without sending trailers"))) { | |||
There was a problem hiding this comment.
This new predicate swallows the annoying, ubiquitous, and seemingly meaningless log:
11/18/2024, 12:23:35 PM warn rdk.networking.signaler.external rpc/wrtc_signaling_answerer.go:242 error communicating with signaling server error rpc error: code = Internal desc = server closed the stream without sending trailers
dgottlieb
approved these changes
Nov 19, 2024
| @@ -39,7 +39,7 @@ type ManagedProcess interface { | |||
|
|
|||
| // NewManagedProcess returns a new, unstarted, from the given configuration. | |||
| func NewManagedProcess(config ProcessConfig, logger utils.ZapCompatibleLogger) ManagedProcess { | |||
| logger = utils.Sublogger(logger, fmt.Sprintf("process.%s_%s", config.ID, config.Name)) | |||
| logger = utils.Sublogger(logger, config.ID) | |||
There was a problem hiding this comment.
Agreed, removing the executable path is not helpful. Just leave a comment that the config.ID maps to the module name in the robot config.
viambot
added
safe to test
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Quiets and removes some logs per SE feedback.
cc @viamrobotics/netcode