Add feature to tune log levels for individual subsystems

[kisunji]

Description

Adds log_sublevels configuration which can fine-tune the log verbosity of individual subcomponents in Consul. This will help users selectively suppress subsystems they may find noisy or help debug certain subsystems by allowing for fine-grained TRACE logs.

Future work

This configuration is not yet reloadable

Examples

Default info logging

$ consul agent -dev -log-level info

...

==> Log data will now stream in as it occurs:

2023-03-17T11:00:57.020-0400 [INFO]  agent.server.raft: initial configuration: index=1 servers="[{Suffrage:Voter ID:6eb83d32-5a63-7307-898a-cd568ee705b0 Address:127.0.0.3:8300}]"
2023-03-17T11:00:57.020-0400 [INFO]  agent.server.raft: entering follower state: follower="Node at 127.0.0.3:8300 [Follower]" leader-address= leader-id=
2023-03-17T11:00:57.021-0400 [INFO]  agent.server.serf.wan: serf: EventMemberJoin: chriskim-C02FX04VMD6R.dc1 127.0.0.3
2023-03-17T11:00:57.021-0400 [INFO]  agent.server.serf.lan: serf: EventMemberJoin: chriskim-C02FX04VMD6R 127.0.0.3
2023-03-17T11:00:57.021-0400 [INFO]  agent.router: Initializing LAN area manager

Trace logging makes all subcomponents noisy

$ consul agent -dev -log-level trace

...

2023-03-17T11:30:47.812-0400 [TRACE] agent.tlsutil: Update: version=1
2023-03-17T11:30:47.813-0400 [TRACE] agent.tlsutil: OutgoingRPCWrapper: version=1
2023-03-17T11:30:47.813-0400 [TRACE] agent.tlsutil: OutgoingALPNRPCWrapper: version=1
2023-03-17T11:30:47.813-0400 [TRACE] agent: [core][Channel #1] Channel created
2023-03-17T11:30:47.814-0400 [TRACE] agent: [core][Channel #1] original dial target is: "consul://dc1.8d1dc4e3-78e3-f3b3-8199-224f91fc8e7f/server.dc1"
2023-03-17T11:30:47.814-0400 [TRACE] agent: [core][Channel #1] parsed dial target is: {Scheme:consul Authority:dc1.8d1dc4e3-78e3-f3b3-8199-224f91fc8e7f Endpoint:server.dc1 URL:{Scheme:consul Opaque: User: Host:dc1.8d1dc4e3-78e3-f3b3-8199-224f91fc8e7f Path:/server.dc1 RawPath: OmitHost:false ForceQuery:false RawQuery: Fragment: RawFragment:}}
2023-03-17T11:30:47.814-0400 [TRACE] agent: [core][Channel #1] Channel authority set to "server.dc1"
2023-03-17T11:30:47.814-0400 [TRACE] agent: [core][Channel #1] Resolver state updated: {
  "Addresses": null,
  "ServiceConfig": null,
  "Attributes": null
} ()
2023-03-17T11:30:47.815-0400 [TRACE] agent: [core][Channel #1] Channel switches to new LB policy "consul-internal"
2023-03-17T11:30:47.815-0400 [TRACE] agent.grpc.balancer: creating balancer: target=consul://dc1.8d1dc4e3-78e3-f3b3-8199-224f91fc8e7f/server.dc1
2023-03-17T11:30:47.815-0400 [DEBUG] agent.grpc.balancer: switching server: target=consul://dc1.8d1dc4e3-78e3-f3b3-8199-224f91fc8e7f/server.dc1 from=<none> to=<none>
2023-03-17T11:30:47.815-0400 [TRACE] agent: [core][Channel #1] Channel Connectivity change to TRANSIENT_FAILURE

Fine-grained trace logging for agent.server.peering-syncer

$ consul agent -dev -log-level warn -log-sublevels agent.server.peering-syncer:trace

...

==> Log data will now stream in as it occurs:

2023-03-17T11:37:47.833-0400 [WARN]  agent.server.raft: heartbeat timeout reached, starting election: last-leader-addr= last-leader-id=
2023-03-17T11:37:47.833-0400 [TRACE] agent.server.peering-syncer: syncing new list of peers: num_peers=0 sequence_id=a71e3343-e22b-6790-3351-df33bc2bbd11
2023-03-17T11:37:47.833-0400 [TRACE] agent.server.peering-syncer: checking connected streams: streams=map[] sequence_id=a71e3343-e22b-6790-3351-df33bc2bbd11
2023-03-17T11:37:47.833-0400 [TRACE] agent.server.peering-syncer: blocking for changes: sequence_id=a71e3343-e22b-6790-3351-df33bc2bbd11
2023-03-17T11:37:47.834-0400 [TRACE] agent.server.peering-syncer: unblocked: sequence_id=a71e3343-e22b-6790-3351-df33bc2bbd11
2023-03-17T11:37:47.834-0400 [TRACE] agent.server.peering-syncer: syncing new list of peers: num_peers=0 sequence_id=fa411fe1-b824-3c33-2789-8bd7c3df12f6
2023-03-17T11:37:47.834-0400 [TRACE] agent.server.peering-syncer: checking connected streams: streams=map[] sequence_id=fa411fe1-b824-3c33-2789-8bd7c3df12f6
2023-03-17T11:37:47.842-0400 [TRACE] agent.server.peering-syncer: blocking for changes: sequence_id=fa411fe1-b824-3c33-2789-8bd7c3df12f6
2023-03-17T11:37:47.842-0400 [TRACE] agent.server.peering-syncer: unblocked: sequence_id=fa411fe1-b824-3c33-2789-8bd7c3df12f6

Limitations

This feature depends on the root Consul logger (named agent) being the parent in the sublogger tree. Some Consul components may use independently created loggers which do not inherit the configuration OR may not be using named subloggers.

Testing & Reproduction steps

• Added new tests
• Tested manually

PR Checklist

• updated test coverage
• external facing docs updated
• not a security concern

[mkeeler]

Great work here! I have wanted this many times myself.

One bikeshed comment would be about the "sublevel" naming. Is that naming a shortened form of subsystem log level? I would probably find something with subsystem or component in the name easier to intuit its use.

[kisunji]

Great work here! I have wanted this many times myself.

One bikeshed comment would be about the "sublevel" naming. Is that naming a shortened form of subsystem log level? I would probably find something with subsystem or component in the name easier to intuit its use.

Would LogSubsystemLevels be clearer? Or LogSubloggerLevel? Open to suggestions!

[jkirschner-hashicorp]

@kisunji : It looks like this allows modifying a subsystem log level at startup. Does it make sense to extend this same functionality to consul monitor, so a subsystem log level can be set during runtime (to assist with debugging an already running agent)?

[kisunji]

@kisunji : It looks like this allows modifying a subsystem log level at startup. Does it make sense to extend this same functionality to consul monitor, so a subsystem log level can be set during runtime (to assist with debugging an already running agent)?

Done! c01ee5e

[kisunji]

@mkeeler is the naming the only blocker for this PR? I believe @lkysow preferred the brevity of -log-sublevels.

[lkysow]

Although I don't super mind either way, just a preference.

[github-actions]

This pull request has been automatically flagged for inactivity because it has not been acted upon in the last 60 days. It will be closed if no new activity occurs in the next 30 days. Please feel free to re-open to resurrect the change if you feel this has happened by mistake. Thank you for your contributions.

[kisunji]

Don't have time to bring this over the finish line but potential improvements:

• break this up into multiple PRs for easier review
• make config reloadable

[zalimeni]

Closing this PR as stale for now, but hoping we can return to it if need arises in the future as this was a really nice improvement.