introduce tracing

[dmah42]

thoroughly untested WIP

this should give us spans around the cells service and logging should be scoped to that but i'm not seeing any obvious output differences so i'm a bit stumped.

going to read around and see if i can figure out if i'm meant to be seeing anything new.

[future-highway]

I didn't notice if you set a subscriber. It may explain why you didn't see a change.

From docs: "For performance reasons, if no currently active subscribers express interest in a given set of metadata by returning true, then the corresponding Span or Event will never be constructed."

A global default subscriber can be set using https://docs.rs/tracing/0.1.37/tracing/subscriber/fn.set_global_default.html

[dmah42]

I didn't notice if you set a subscriber. It may explain why you didn't see a change.

From docs: "For performance reasons, if no currently active subscribers express interest in a given set of metadata by returning true, then the corresponding Span or Event will never be constructed."

A global default subscriber can be set using https://docs.rs/tracing/0.1.37/tracing/subscriber/fn.set_global_default.html

the method i'm using sets a subscriber.

what's happening is that on trace level I see the traces around the logs (yay) but a) the span entry has nothing interesting (fixable) and b) every crate is logging traces. my attempt to set an env filter didn't resolve this as I thought it might (trace only for auraed) so I need to tweak that further.

[dmah42]

it helps if you call the right thing.. init not finish.

[dmah42]

example output:

2022-12-20T11:31:58.835465Z  INFO auraed: Starting Aurae Daemon Runtime...
2022-12-20T11:31:58.836538Z  INFO auraed: Register Server SSL Identity
2022-12-20T11:31:58.836828Z  INFO auraed: Validating SSL Identity and Root Certificate Authority (CA)
2022-12-20T11:31:58.837697Z  INFO auraed: User Access Socket Created: /var/run/aurae/aurae.sock
2022-12-20T11:32:02.112573Z  INFO allocate: auraed::runtime::cells::cell_service: CellService: allocate() cell=ValidatedCell { name: CellName("sleeper-cell"), cpu_cpus: CpuCpus(""), cpu_shares: CpuWeight(2), cpu_mems: CpusetMems(""), cpu_quota: CpuQuota(400000), ns_share_mount: false, ns_share_uts: false, ns_share_ipc: false, ns_share_pid: false, ns_share_net: false, ns_share_cgroup: false } request=ValidatedAllocateCellRequest { cell: ValidatedCell { name: CellName("sleeper-cell"), cpu_cpus: CpuCpus(""), cpu_shares: CpuWeight(2), cpu_mems: CpusetMems(""), cpu_quota: CpuQuota(400000), ns_share_mount: false, ns_share_uts: false, ns_share_ipc: false, ns_share_pid: false, ns_share_net: false, ns_share_cgroup: false } }
2022-12-20T11:32:02.209044Z  INFO start: auraed::runtime::cells::cell_service: CellService: start() cell_name=sleeper-cell executable=ValidatedExecutable { name: ExecutableName("sleep-42"), command: "/usr/bin/sleep", args: ["42"], description: "Sleep for 42 seconds" } request=ValidatedStartExecutableRequest { cell_name: CellName("sleeper-cell"), executable: ValidatedExecutable { name: ExecutableName("sleep-42"), command: "/usr/bin/sleep", args: ["42"], description: "Sleep for 42 seconds" } }
2022-12-20T11:32:02.209743Z  INFO start: auraed::runtime::cells::executable: Unshare: mount request=ValidatedStartExecutableRequest { cell_name: CellName("sleeper-cell"), executable: ValidatedExecutable { name: ExecutableName("sleep-42"), command: "/usr/bin/sleep", args: ["42"], description: "Sleep for 42 seconds" } }
2022-12-20T11:32:02.209977Z  INFO start: auraed::runtime::cells::executable: Unshare: uts request=ValidatedStartExecutableRequest { cell_name: CellName("sleeper-cell"), executable: ValidatedExecutable { name: ExecutableName("sleep-42"), command: "/usr/bin/sleep", args: ["42"], description: "Sleep for 42 seconds" } }
2022-12-20T11:32:02.210072Z  INFO start: auraed::runtime::cells::executable: Unshare: ipc request=ValidatedStartExecutableRequest { cell_name: CellName("sleeper-cell"), executable: ValidatedExecutable { name: ExecutableName("sleep-42"), command: "/usr/bin/sleep", args: ["42"], description: "Sleep for 42 seconds" } }
2022-12-20T11:32:02.210403Z  INFO start: auraed::runtime::cells::executable: Unshare: pid request=ValidatedStartExecutableRequest { cell_name: CellName("sleeper-cell"), executable: ValidatedExecutable { name: ExecutableName("sleep-42"), command: "/usr/bin/sleep", args: ["42"], description: "Sleep for 42 seconds" } }
2022-12-20T11:32:02.210607Z  INFO start: auraed::runtime::cells::executable: Unshare: net request=ValidatedStartExecutableRequest { cell_name: CellName("sleeper-cell"), executable: ValidatedExecutable { name: ExecutableName("sleep-42"), command: "/usr/bin/sleep", args: ["42"], description: "Sleep for 42 seconds" } }
2022-12-20T11:32:02.210821Z  INFO start: auraed::runtime::cells::executable: Unshare: cgroup request=ValidatedStartExecutableRequest { cell_name: CellName("sleeper-cell"), executable: ValidatedExecutable { name: ExecutableName("sleep-42"), command: "/usr/bin/sleep", args: ["42"], description: "Sleep for 42 seconds" } }
2022-12-20T11:32:02.213609Z  INFO start: auraed::runtime::cells::executable: CellService: aurae_process_pre_exec(): sleep-42 request=ValidatedStartExecutableRequest { cell_name: CellName("sleeper-cell"), executable: ValidatedExecutable { name: ExecutableName("sleep-42"), command: "/usr/bin/sleep", args: ["42"], description: "Sleep for 42 seconds" } }
2022-12-20T11:32:02.242623Z  INFO start: auraed::runtime::cells::cell: Cells: cell_name=sleeper-cell executable_name=sleep-42 spawn() -> pid=CgroupPid { pid: 2532814 } request=ValidatedStartExecutableRequest { cell_name: CellName("sleeper-cell"), executable: ValidatedExecutable { name: ExecutableName("sleep-42"), command: "/usr/bin/sleep", args: ["42"], description: "Sleep for 42 seconds" } }
2022-12-20T11:32:02.308121Z  INFO stop: auraed::runtime::cells::cell_service: CellService: stop() cell_name=CellName("sleeper-cell") executable_name=ExecutableName("sleep-42") request=ValidatedStopExecutableRequest { cell_name: CellName("sleeper-cell"), executable_name: ExecutableName("sleep-42") }
2022-12-20T11:32:02.309093Z  INFO stop: auraed::runtime::cells::executable: Executable with pid 2532814 exited with status killed by signal SIGKILL[9] request=ValidatedStopExecutableRequest { cell_name: CellName("sleeper-cell"), executable_name: ExecutableName("sleep-42") }
2022-12-20T11:32:02.374573Z  INFO free: auraed::runtime::cells::cell_service: CellService: free() cell_name=CellName("sleeper-cell") request=ValidatedFreeCellRequest { cell_name: CellName("sleeper-cell") }

[dmah42]

big open question: should this setup that is currently in auraed::main instead be moved to the observe subsystem and replace the current multi-logger setup (given tracing can do multiple subscribers)?

[dmah42]

big open question: should this setup that is currently in auraed::main instead be moved to the observe subsystem and replace the current multi-logger setup (given tracing can do multiple subscribers)?

decided for myself :)