[RFE] trace - Allow granularity control over error messages

[galofir-ms]

Current situation

• No control over warning/error messages that are allowed
• Warning/Errors are being printed to stdout stream

To verify, I set up listeners to stdout and stderr and ran the exec, warn/errors were streamd to stdout and stderr listener never got evoked

time="2023-12-26T14:12:14Z" level=warning msg="Failed to parse event [stdout stream] - time=\"2023-12-26T14:12:14Z\" level=warning msg=\"Runtime enricher (docker): failed to get container: it is a pause container\""

Impact

• We are listening to stdout stream for valid processes, when an error/warning msg is emitted to stdout as well we have to handle it, impacting our processing performance and internal test suites.
  it would be better to emit such errors to stderr, or at least allow us to control whether or not errors should be passed to the stdout pipe.

Implementation options

I would consider 3 possible solutions:

Emit to stderr

ig trace exec [ARGS]... --emit-stderr

Ignore errors all together (not recommended but probably easiest)

ig trace exec [ARGS]... --silent

Allow to whitelist errors (probably with error codes)

ig trace exec [ARGS]... --ignore-error RuntimeEnricher --ignore-error CGroupEnricher ....

[galofir-ms]

Relevant logrus issue and discussion:
sirupsen/logrus#403

[mauriciovasquezbernal]

Warning/Errors are being printed to stdout stream

Are 100% sure this is true? I used annotate-output and I see that warning messages are going to stderr:

$ sudo annotate-output ig trace exec -v
15:08:04 I: Started ig trace exec -v
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="bpf already mounted"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="debugfs already mounted"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="tracefs already mounted"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(docker): Skip container \"keen_faraday\" (ID: e6872ba63becf23dbcc3705ef9c904d584e3e665656665e84a673b34bfe136e1): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"00d5fa00a167b639073eb67c6efab56f2f270852578d8de1516c3d42807650d4\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"06d2df6d47cb2f864c20b79964dd4408d44bba41a1dd229ee008ca8093a8d6d2\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"079a1a3be64c9ac0e3e90e2ee9d962e5824d6bbd776dc9186b73fa1d7d057c9d\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"1222ca53c790137754d57efdf51f22d495ff32d14d437f4120a19b9d363e5638\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"14bd2521cc92e82092c0a21dda5f74414c3281b1cbd932d31e14f7ae68350ecf\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"15740c0a266bf88079eca97a3842ac1a130ff248624badaa6204ec6802cc6563\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"1734f187e82203880aeb36957e69b80f187e9d9ebc5e7cca7a528c9d276d1ec8\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"1b0e9e2e0aec6f50326ddbffdcd2f1b51607c84ed8c03462a5d295d2804f96c9\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"1b56bde2c4e9f1714cfcc9df8b0bb499d3a593dff7a09cae10498c6ce4414a10\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"1e36be5895fe56bab7a45121515599051f09c3c3d64cec06414535a893f7910d\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"20ed798a2c16e931292eda1faf6b78ad19b6b4f70a0b1cc8f045948d716939a0\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"2b6e1088016be33f2bc36acf8f993f9e7ab4a938c1098fa0df261235b1be0f25\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"2d7ca4116235ad54ebf3dd90287310bb2e7fe8604eedb56894e14c6ae53a28ae\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"327e295859a2fec642555ddf958f31981f81e24c4c270d9d0c256cde4accc5f1\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"4715b40b26b1c21b0ef7f6ce702cdffbb013881973b15e63262203c5a8f89de5\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"4c63e10e82189d6e61effa612eb6359750cd64b3afa9ac977390c028c209c883\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"53c2d05d0d0ecedef626af44ef9cf87ddb24cdee51e132e97c7f9506f5aea474\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"56002ad18fd4b2b76aa5c78f673014acf3fdb6867546f54426859562bdc4113f\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"57c6dd06d157509d0b3bba2035cbb99c11ab5984b57a756d4e6f7a3803ee4261\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"57e93cb411887e2ad6de313bccb33758802d3eb459ab76fd2b6f7af60d2b58c0\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"5cae99b8543a4b1aee08f55b3569de5bcc1e250bdb1e1af0249d138c38b282e9\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"6336f3fcff5cd5108c270ef18082995b93c219a2213acb27ade86cc63b65d161\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"633d1c992b7fcc5eb54da4405ec84d17099b6c44d7b366b578ad4387478c7454\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"6516d8c6ade142db60cd20e997ff02db85ccc4cb234796ba620c73b3fa42598e\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"65fd74136d319b787997dee206b950bf214db47c41fbd7cfcb0f11149c9a97b1\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"67af41d4b85e7aded19ef4aa7d4978e3c461a9f74fe08ac36975ff7375f6d215\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"67e696cd9c3eae32b49f68051a9a05abfd5d8a6fecfcb3780f9ac83bb53bf97a\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"78f03ef1e448c7bf439131a4a6300e28c72807477d63efb33e77cc957f001661\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"7c03908bb7f6dce0aec90bfe451194c7cde0b514c98a265f8fd01420602e0810\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"82bfe8ae7bd4999dc250d06a21204ab9eea811a2dfec531bb2b7c5c65977832e\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"88724411dc8fda9ec9b1b00ac61c811a0710f47d56e42c060f7d1ee0150f5db7\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"8c05da974a0c8791222f276545cc77be94fd4baac8955952e6be639ca1a410cc\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"8c9509895eda4eb1ed408fefbb2a7a9ba31af68dc61e58ab4d5df8ae5ab232ab\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"a4be7d3e40fa1af249d04f75f611e5e211f4ba655bf4352c4709941591dca289\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"a8794ca167424e2328fcce30f1ac2bd052e061afac970ade03d58d42fcec4763\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"b7773ea3a608b2e61f5e98fcb89b2bc5e91a3ce0dcbde567893226eb199838a2\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"bd0a092971232fd47c4e863cbe80029802e7cbd5c97c6dde10a5169fbb4f37d4\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"be7dc3d432c2bc243f7105fde87dd2eb79546d0b328c349a5e9e4920012c8eda\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"bef018b92f79e33decdf3fa21a4f7775ba504238e2c8879e053217490f4e01f2\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"c2b20ec63d46eb9c8d262364726e7d04fdbcaedb1ff216fbb1e7fbbc9f301340\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"c760e0cf6a1310dfcffbee710d2c3e3a0fd00184c03c31405728d21d2edb09e0\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"c870dc8ea339dcd5b99e5837636395659b64590a3bf8d2576f38e36d4f2cb06a\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"ce9529c69407acad6ecda1dd8f81fa9604bc61c53e206be3b6a23e72df81cf71\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"def99b07dbae47e5f3447caeca0ef399f5261a4786b5c552c0b74ef6a71b523b\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"dfe07c069d16c6a0a0e0d4abf07daed687c5ccace0ab88b821d93140a5e84d6a\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"e01a4341352b9cf24c37282b13163fcb7ccfefebd575fc31ec481b193d9417e6\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"f3e488fca75d36e0fc55a6bb05a9e0ed0b4dd02519277f665a5469013dd70bd3\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container \"f411769cad0d1a2c310a56c825d3847dc798296f2e5e88d693cb7e3284e752d2\" is a sandbox container. Temporary skipping it" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="No task for \"f6b144a846d3eca051cfe51fea952790691267069acdee0de51fae0c10816f34\". Assuming it is in \"created\" status" container-client=containerd
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"tetragon\" (ID: 00d5fa00a167b639073eb67c6efab56f2f270852578d8de1516c3d42807650d4): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"mount-bpffs\" (ID: 06d2df6d47cb2f864c20b79964dd4408d44bba41a1dd229ee008ca8093a8d6d2): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"kube-controller-manager\" (ID: 079a1a3be64c9ac0e3e90e2ee9d962e5824d6bbd776dc9186b73fa1d7d057c9d): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"etcd\" (ID: 15740c0a266bf88079eca97a3842ac1a130ff248624badaa6204ec6802cc6563): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"kube-scheduler\" (ID: 1b0e9e2e0aec6f50326ddbffdcd2f1b51607c84ed8c03462a5d295d2804f96c9): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"mypod10\" (ID: 1e36be5895fe56bab7a45121515599051f09c3c3d64cec06414535a893f7910d): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"install-cni\" (ID: 2d7ca4116235ad54ebf3dd90287310bb2e7fe8604eedb56894e14c6ae53a28ae): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"upgrade-ipam\" (ID: 327e295859a2fec642555ddf958f31981f81e24c4c270d9d0c256cde4accc5f1): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"calico-node\" (ID: 57e93cb411887e2ad6de313bccb33758802d3eb459ab76fd2b6f7af60d2b58c0): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"kube-proxy\" (ID: 633d1c992b7fcc5eb54da4405ec84d17099b6c44d7b366b578ad4387478c7454): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"kube-apiserver\" (ID: 65fd74136d319b787997dee206b950bf214db47c41fbd7cfcb0f11149c9a97b1): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"export-stdout\" (ID: 82bfe8ae7bd4999dc250d06a21204ab9eea811a2dfec531bb2b7c5c65977832e): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"calico-kube-controllers\" (ID: 88724411dc8fda9ec9b1b00ac61c811a0710f47d56e42c060f7d1ee0150f5db7): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"tigera-operator\" (ID: a4be7d3e40fa1af249d04f75f611e5e211f4ba655bf4352c4709941591dca289): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"coredns\" (ID: a8794ca167424e2328fcce30f1ac2bd052e061afac970ade03d58d42fcec4763): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"ig\" (ID: be7dc3d432c2bc243f7105fde87dd2eb79546d0b328c349a5e9e4920012c8eda): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"gadget\" (ID: c2b20ec63d46eb9c8d262364726e7d04fdbcaedb1ff216fbb1e7fbbc9f301340): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"tetragon-operator\" (ID: def99b07dbae47e5f3447caeca0ef399f5261a4786b5c552c0b74ef6a71b523b): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"coredns\" (ID: dfe07c069d16c6a0a0e0d4abf07daed687c5ccace0ab88b821d93140a5e84d6a): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(containerd): Skip container \"nginx\" (ID: f6b144a846d3eca051cfe51fea952790691267069acdee0de51fae0c10816f34): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=warning msg="Runtime enricher (cri-o): couldn't get current containers: listing containers with request &ListContainersRequest{Filter:nil,}: rpc error: code = Unavailable desc = connection error: desc = \"transport: Error while dialing: dial unix /run/crio/crio.sock: connect: no such file or directory\""
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="Runtime enricher(podman): Skip container \"vigorous_wilbur\" (ID: fcf449f99bb7fa361385d0746a85af299b3a9304c9f6867f9272f3f9bf8d7388): not running"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: trying runtime at /bin/runc"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: runc at /bin/runc not found"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: trying runtime at /usr/bin/runc"
15:08:15 O: RUNTIME.CONTAINERNAME          PID              PPID             COMM             RET ARGS                                    
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: runc at /usr/bin/runc not found"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: trying runtime at /usr/sbin/runc"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: trying runtime at /usr/local/bin/runc"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: runc at /usr/local/bin/runc not found"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: trying runtime at /usr/local/sbin/runc"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: runc at /usr/local/sbin/runc not found"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: trying runtime at /usr/lib/cri-o-runc/sbin/runc"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: runc at /usr/lib/cri-o-runc/sbin/runc not found"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: trying runtime at /run/torcx/unpack/docker/bin/runc"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: runc at /run/torcx/unpack/docker/bin/runc not found"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: trying runtime at /usr/bin/crun"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: runc at /usr/bin/crun not found"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="container-hook: trying runtime at /usr/bin/conmon"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="> canEnrichEvent: true"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="\t> canEnrichEventFromMountNs: true"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="\t> canEnrichEventFromNetNs: false"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="> isMountNsMapSetter: true"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="> isAttacher: false"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="running with local runtime"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="found 1 operators: "
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="  LocalManager"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="set event handler"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="calling operator.PreGadgetRun()"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="set mountnsmap for gadget"
15:08:15 E: time="2024-01-03T15:08:15Z" level=debug msg="calling gadget.Run()"

Also, I checked the logrus implementation and it logs by default to std err -> https://github.com/sirupsen/logrus/blob/v1.9.3/logger.go#L18-L21

Can you please double check if those are really going to stdout on your env, if yes, would you mind providing more details to reproduce this?