Skip to content

feat: implement log filtering

Maksim Kaitmazian requested to merge max/issue-745/separate-log-streams into master

Summary

  • feat: implement log filtering

This commit changes log.level option to log.filter. The new option can be used as the old one, but, in addition, it allows to specify module specific filters.

For instance, here is how pgproto logs can be filtered:

PICODATA_LOG_FILTER="pgproto=debug" picodata run -i --pg-listen localhost:5433
[supervisor:170380] running StartDiscover
2024-10-07 14:06:43.156 [182045] main/104/interactive I> starting postgres server at ("localhost", 5433)...
2024-10-07 14:06:43.156 [182045] main/124/pgproto I> creating statement storage with capacity 1024
2024-10-07 14:06:43.156 [182045] main/124/pgproto I> creating portal storage with capacity 1024
2024-10-07 14:07:00.511 [182045] main/124/pgproto I> spawning a new fiber for postgres client connection
2024-10-07 14:07:00.511 [182045] main/139/pgproto::client V> received 84 bytes from client
2024-10-07 14:07:00.511 [182045] main/139/pgproto::client V> received StartupPacket from client
2024-10-07 14:07:00.511 [182045] main/139/pgproto::client V> client parameters: {"application_name": "psql", "client_encoding": "UTF8", "database": "postgres", "user": "postgres"}
2024-10-07 14:07:00.512 [182045] main/139/pgproto::client I> processed startup
2024-10-07 14:07:00.513 [182045] main/139/pgproto::client V> received 41 bytes from client
2024-10-07 14:07:00.513 [182045] main/139/pgproto::client I> client authenticated
2024-10-07 14:07:00.513 [182045] main/139/pgproto::client I> entering the message handling loop
...

In the following example a global log level is set, but logs for pgproto, governor, vshard and box are disabled:

PICODATA_LOG_FILTER="info,pgproto=off,governor=off,vshard=off,box=off" picodata run -i --pg-listen localhost:5433
[supervisor:533175] running StartDiscover
2024-10-07 21:42:55.937 [533722] main/104/interactive I> 'cluster.default_replication_factor': 1
2024-10-07 21:42:55.937 [533722] main/104/interactive I> 'instance.data_dir': "."
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.tier': "default"
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.failure_domain': {}
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.listen': "127.0.0.1:3301"
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.advertise_address': "127.0.0.1:3301"
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.peer': ["127.0.0.1:3301"]
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.admin_socket': "./admin.sock"
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.shredding': false
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.log.filter': "info,pgproto=off,governor=off,vshard=off,box=off"
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.log.format': "plain"
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.memtx.memory': "64M"
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.memtx.checkpoint_count': 2
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.memtx.checkpoint_interval': 3600
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.vinyl.memory': "128M"
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.vinyl.cache': "128M"
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.iproto.max_concurrent_messages': 768
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.pg.listen': "localhost:5433"
2024-10-07 21:42:55.938 [533722] main/104/interactive I> 'instance.pg.ssl': false
2024-10-07 21:42:55.938 [533722] main/104/interactive I> entering discovery phase
2024-10-07 21:42:55.939 [533722] main/104/interactive I> Tarantool 2.11.2-144-g06f1d78b6 Linux-x86_64-RelWithDebInfo
2024-10-07 21:42:55.940 [533722] main/104/interactive I> log level 7
2024-10-07 21:42:55.987 [533722] main/104/interactive I> entering post-join phase
2024-10-07 21:42:55.988 [533722] main/104/interactive I> switched to configuration, config: Configuration { voters: Configuration { incoming: Configuration { voters: {1} }, outgoing: Configuration { voters: {} } }, learners: {}, learners_next: {}, auto_leave: false }, raft_id: 1
2024-10-07 21:42:55.988 [533722] main/104/interactive I> became follower at term 11, term: 11, raft_id: 1
2024-10-07 21:42:55.988 [533722] main/104/interactive I> newRaft, peers: Configuration { incoming: Configuration { voters: {1} }, outgoing: Configuration { voters: {} } }, last term: 11, last index: 89, applied: 89, commit: 89, term: 11, raft_id: 1
2024-10-07 21:42:55.988 [533722] main/104/interactive I> RawNode created with id 1., id: 1, raft_id: 1
2024-10-07 21:42:55.989 [533722] main/104/interactive I> this is the only voter in cluster, triggering election immediately
2024-10-07 21:42:55.989 [533722] main/104/interactive I> starting a new election, term: 11, raft_id: 1
2024-10-07 21:42:55.989 [533722] main/104/interactive I> became pre-candidate at term 11, term: 11, raft_id: 1
2024-10-07 21:42:55.989 [533722] main/104/interactive I> became candidate at term 12, term: 12, raft_id: 1
2024-10-07 21:42:55.990 [533722] main/104/interactive I> became leader at term 12, term: 12, raft_id: 1
2024-10-07 21:42:55.990 [533722] main/104/interactive I> tx_binary: bound to 127.0.0.1:3301
2024-10-07 21:42:55.991 [533722] main/104/interactive/socket I> tcp_server: remove dead UNIX socket: ././admin.sock
2024-10-07 21:42:55.991 [533722] main/118/console/unix/:././admin.sock/socket I> started
2024-10-07 21:42:55.991 [533722] main/104/interactive I> initiating self-activation of i1
2024-10-07 21:42:56.094 [533722] main/104/interactive I> self-activated successfully
2024-10-07 21:42:56.096 [533722] main/104/interactive I> skipped luaL_loadfile due to picodata callback
2024-10-07 21:42:56.096 [533722] main/104/interactive C> Tarantool 2.11.2-144-g06f1d78b6
type 'help' for interactive help
picodata>
Edited by Maksim Kaitmazian

Merge request reports