# zephyr samples/subsys/logging/logger/README.rst
[00:00:00.106,051] <inf> sample_module: log in test_module 11 ⇒ {"rule": "zephyr", "level": "info", "name": "sample_module", "device_ns": 106051000, "message": "sample_module: log in test_module 11", "prefixed": true, "values": []}
[00:00:00.106,054] <inf> sample_module: Inline function. ⇒ {"rule": "zephyr", "level": "info", "name": "sample_module", "device_ns": 106054000, "message": "sample_module: Inline function."}
[00:00:00.106,200] <inf> sample_instance.inst1: Inline call. ⇒ {"rule": "zephyr", "level": "info", "device_ns": 106200000, "message": "sample_instance.inst1: Inline call.", "name": "sample_instance.inst1"}
[00:00:00.106,204] <inf> sample_instance.inst1: counter_value: 0 ⇒ {"rule": "zephyr", "level": "info", "message": "sample_instance.inst1: counter_value: 0", "values": [], "name": "sample_instance.inst1"}
[00:00:00.106,209] <wrn> sample_instance.inst1: Example of hexdump: ⇒ {"rule": "zephyr", "level": "warn", "device_ns": 106209000, "name": "sample_instance.inst1", "message": "sample_instance.inst1: Example of hexdump:"}
[00:00:00.106,223] <wrn> sample_instance.inst2: Example of hexdump: ⇒ {"rule": "zephyr", "level": "warn", "device_ns": 106223000, "name": "sample_instance.inst2", "message": "sample_instance.inst2: Example of hexdump:"}
[00:00:01.122,316] <inf> main: Logging transient string:transient_string ⇒ {"rule": "zephyr", "level": "info", "name": "main", "device_ns": 1122316000, "message": "main: Logging transient string:transient_string"}
[00:00:01.122,348] <err> main: Error message example. ⇒ {"rule": "zephyr", "level": "error", "name": "main", "device_ns": 1122348000, "message": "main: Error message example."}
[00:00:01.122,352] <wrn> main: Warning message example. ⇒ {"rule": "zephyr", "level": "warn", "name": "main", "device_ns": 1122352000, "message": "main: Warning message example."}
[00:00:01.122,355] <inf> main: Info message example. ⇒ {"rule": "zephyr", "level": "info", "name": "main", "device_ns": 1122355000, "message": "main: Info message example."}
[00:00:02.151,602] <inf> main: performance test - log message 0 ⇒ {"rule": "zephyr", "level": "info", "name": "main", "device_ns": 2151602000, "message": "main: performance test - log message 0", "values": []}
[00:00:03.165,977] <err> ext_log_system: critical level log ⇒ {"rule": "zephyr", "level": "error", "name": "ext_log_system", "device_ns": 3165977000, "message": "ext_log_system: critical level log"}
[00:00:03.165,991] <err> ext_log_system: error level log, 1 arguments: 1 ⇒ {"rule": "zephyr", "level": "error", "name": "ext_log_system", "message": "ext_log_system: error level log, 1 arguments: 1", "values": []}
[00:00:03.166,044] <inf> ext_log_system: info level log, 4 arguments : 1 24 ⇒ {"rule": "zephyr", "level": "info", "name": "ext_log_system", "device_ns": 3166044000, "message": "ext_log_system: info level log, 4 arguments : 1 24", "values": []}
# a Zephyr board, after escape removal
[00:00:00.020,000] <inf> dcdc: rail=13.65V in=4.50A limit=4.5A temp=35.0C ⇒ {"rule": "zephyr+kv", "level": "info", "name": "dcdc", "device_ns": 20000000, "message": "dcdc: rail=13.65V in=4.50A limit=4.5A temp=35.0C", "prefixed": true, "values": [["rail", 13.65, "V"], ["in", 4.5, "A"], ["limit", 4.5, "A"], ["temp", 35.0, "C"]]}
[00:00:05.000,000] <wrn> bms: cell imbalance 37mV ⇒ {"rule": "zephyr", "level": "warn", "name": "bms", "device_ns": 5000000000, "message": "bms: cell imbalance 37mV", "values": []}
# zephyr tests/subsys/logging/log_output/src/log_output_test.c expectations, with the level flag added
# constructed [00:00:01.000,000] <inf> domain/src: test ⇒ {"rule": "zephyr", "level": "info", "name": "src", "device_ns": 1000000000, "message": "domain/src: test"}
# constructed [1193046:28:17.000,000] <inf> domain/src: test ⇒ {"rule": "zephyr", "level": "info", "name": "src", "device_ns": 4294967297000000000, "message": "domain/src: test"}
# the same test with CONFIG_LOG_OUTPUT_FORMAT_LINUX_TIMESTAMP
# constructed [4294967297.000000] <inf> domain/src: test ⇒ {"rule": "zephyr", "level": "info", "name": "src", "device_ns": 4294967297000000000, "message": "domain/src: test", "prefixed": true}
# constructed [    1.106051] <err> main: Error message example. ⇒ {"rule": "zephyr", "level": "error", "name": "main", "device_ns": 1106051000, "message": "main: Error message example."}
# constructed [    0.020000] <inf> dcdc: rail=13.65V ⇒ {"rule": "zephyr+kv", "level": "info", "name": "dcdc", "device_ns": 20000000, "message": "dcdc: rail=13.65V", "values": [["rail", 13.65, "V"]]}
# log_output.c since 3.2: the function-name prefix follows the name
# constructed [00:00:10.250,500] <dbg> dcdc: dcdc_poll: sample 3 ⇒ {"rule": "zephyr", "level": "debug", "name": "dcdc", "message": "dcdc: dcdc_poll: sample 3"}
# Zephyr 2.7 printed the function after a dot, which reads as part of the name
# constructed [00:00:10.250,500] <dbg> dcdc.dcdc_poll: sample 3 ⇒ {"rule": "zephyr", "level": "debug", "device_ns": 10250500000, "message": "dcdc.dcdc_poll: sample 3", "name": "dcdc.dcdc_poll"}
# constructed [25:00:00.000,001] <inf> main: up a day ⇒ {"rule": "zephyr", "level": "info", "name": "main", "device_ns": 90000000001000, "message": "main: up a day"}
# constructed [01:02:03.004,005] <inf> net-mgmt: link up ⇒ {"rule": "zephyr", "level": "info", "name": "net-mgmt", "device_ns": 3723004005000, "message": "net-mgmt: link up"}
# constructed [00:00:00.500,000] <inf> main counter 5 ⇒ {"rule": "plain", "level": "info", "message": "[00:00:00.500,000] <inf> main counter 5"}
# log_output.c with CONFIG_LOG_OUTPUT_FORMAT_DATE_TIMESTAMP or _ISO8601_TIMESTAMP: wall-clock time
# a date in 1970 is the uptime: log_output.c turns the timestamp into a date, and with no real-time
# source it counts from boot
# constructed [1970-01-01 00:00:01.000,000] <err> main: Error message example. ⇒ {"rule": "zephyr", "level": "error", "name": "main", "device_ns": 1000000000, "stamp": null, "message": "main: Error message example."}
# constructed [1970-01-02 01:00:00.000,001] <inf> main: a day up ⇒ {"rule": "zephyr", "level": "info", "name": "main", "device_ns": 90000000001000, "stamp": null, "message": "main: a day up"}
# constructed [1970-01-01T00:00:05,250000Z] <inf> main: iso ⇒ {"rule": "zephyr", "level": "info", "name": "main", "device_ns": 5250000000, "stamp": null, "message": "main: iso"}
# constructed [1970-02-31 00:00:01.000,000] <inf> main: no such day ⇒ {"rule": "zephyr", "level": "info", "name": "main", "device_ns": null, "message": "main: no such day"}
# constructed [2024-05-01T10:00:00,000000Z] <inf> m: x ⇒ {"rule": "zephyr", "level": "info", "name": "m", "device_ns": null, "message": "m: x"}
# log_output.c ids_print(): CONFIG_LOG_THREAD_ID_PREFIX "[%3d %s] " or "[irq] ", CONFIG_LOG_CORE_ID_PREFIX "[core %d] "
# constructed [00:00:00.106,051] <inf> [  0 main] sample_module: msg ⇒ {"rule": "zephyr", "level": "info", "name": "sample_module", "device_ns": 106051000, "message": "[  0 main] sample_module: msg"}
# constructed [00:00:00.106,051] <wrn> [ -1 sysworkq] dcdc: rail=13.65V ⇒ {"rule": "zephyr+kv", "level": "warn", "name": "dcdc", "message": "[ -1 sysworkq] dcdc: rail=13.65V", "values": [["rail", 13.65, "V"]]}
# constructed [00:00:00.106,051] <err> [irq] uart: overrun ⇒ {"rule": "zephyr", "level": "error", "name": "uart", "message": "[irq] uart: overrun"}
# constructed [00:00:00.106,051] <inf> [core 1] ipc: ready ⇒ {"rule": "zephyr", "level": "info", "name": "ipc", "message": "[core 1] ipc: ready"}
# constructed [00:00:00.106,051] <inf> [  5 main] [core 0] domain/src: test ⇒ {"rule": "zephyr", "level": "info", "name": "src", "message": "[  5 main] [core 0] domain/src: test"}
# zephyr v4.4.2 tests/subsys/logging/log_output/src/log_output_test.c: no stamp when LOG_BACKEND_SHOW_TIMESTAMP is off
<err> src: test ⇒ {"rule": "zephyr", "level": "error", "name": "src", "device_ns": null, "message": "src: test", "body": "test", "prefixed": true}
<wrn> src: test ⇒ {"rule": "zephyr", "level": "warn", "name": "src", "device_ns": null, "message": "src: test"}
<inf> src: test ⇒ {"rule": "zephyr", "level": "info", "leveled": true, "name": "src", "message": "src: test"}
<dbg> src: test ⇒ {"rule": "zephyr", "level": "debug", "name": "src", "message": "src: test"}
<inf> domain/src: test ⇒ {"rule": "zephyr", "level": "info", "name": "src", "message": "domain/src: test", "body": "test"}
# constructed <err> [  5 main] src: Test ⇒ {"rule": "zephyr", "level": "error", "name": "src", "message": "[  5 main] src: Test"}
# zephyr v4.4.2 samples/arch/mpu/mpu_test/README.rst
<err> os: ***** BUS FAULT ***** ⇒ {"rule": "zephyr", "level": "error", "name": "os", "message": "os: ***** BUS FAULT *****", "body": "***** BUS FAULT *****"}
<err> os:   Precise data bus error ⇒ {"rule": "zephyr", "level": "error", "name": "os", "message": "os:   Precise data bus error", "body": "  Precise data bus error"}
<err> os: Faulting instruction address (r15/pc): 0x000003c8 ⇒ {"rule": "zephyr", "level": "error", "name": "os", "message": "os: Faulting instruction address (r15/pc): 0x000003c8"}
<err> os: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0 ⇒ {"rule": "zephyr", "level": "error", "name": "os", "message": "os: >>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0", "body": ">>> ZEPHYR FATAL ERROR 0: CPU exception on CPU 0"}
<err> os: Halting system ⇒ {"rule": "zephyr", "level": "error", "name": "os", "message": "os: Halting system", "body": "Halting system"}
# log_output.c prefix_print(): CONFIG_LOG_TAG_MAX_LEN prints the tag and a space first; an empty tag leaves the space
# constructed acme [00:00:01.000,000] <inf> src: test ⇒ {"rule": "zephyr", "level": "info", "name": "src", "device_ns": 1000000000, "message": "src: test"}
# constructed  [00:00:01.000,000] <inf> src: test ⇒ {"rule": "zephyr", "level": "info", "name": "src", "device_ns": 1000000000, "message": "src: test"}
# constructed acme <wrn> src: test ⇒ {"rule": "zephyr", "level": "warn", "name": "src", "device_ns": null, "message": "src: test"}
# constructed pump-7 [    1.000000] <err> dcdc: trip ⇒ {"rule": "zephyr", "level": "error", "name": "dcdc", "device_ns": 1000000000, "message": "dcdc: trip"}
# constructed long-tag~ [1970-01-01 00:00:01.000,000] <inf> src: test ⇒ {"rule": "zephyr", "level": "info", "name": "src", "device_ns": 1000000000, "message": "src: test"}

# zephyr v4.4.2 subsys/logging/backends/log_backend_net.c and log_output.c syslog_print(): RFC 5424, the thread as the app, no level tag
# constructed <134>1 1970-01-01T00:00:01.000000Z zephyr - - - - src: test ⇒ {"rule": "syslog", "level": "info", "message": "src: test"}
# constructed <131>1 1970-01-01T00:00:01.000000Z zephyr main - - - src: failed ⇒ {"rule": "syslog", "level": "error", "name": "main", "message": "src: failed"}
# nRF5's NRF_LOG prints whole level words: zephyr doc/services/logging/index.rst shows its form
[00:00:00.000,274] <info> sample_instance.inst1: logging message ⇒ {"rule": "nrf5", "level": "info", "name": "sample_instance.inst1", "device_ns": 274000, "message": "sample_instance.inst1: logging message"}
# constructed acme  <inf> src: test ⇒ {"rule": "plain", "level": "info", "message": "acme  <inf> src: test"}
# constructed <inf>src: test ⇒ {"rule": "plain", "level": "info", "message": "<inf>src: test"}
# constructed see <inf> tags ⇒ {"rule": "plain", "level": "info", "message": "see <inf> tags"}
Module logging showcase. ⇒ {"rule": "plain", "level": "info", "message": "Module logging showcase."}
01 02 03 04             |.... ⇒ {"rule": "plain", "level": "info", "message": "01 02 03 04             |....", "values": []}
Estimated logging capabilities: 42000000 messages/second ⇒ {"rule": "plain", "level": "info", "message": "Estimated logging capabilities: 42000000 messages/second", "values": []}
Booting Zephyr OS build v4.4.2 ⇒ {"rule": "plain", "level": "info", "message": "Booting Zephyr OS build v4.4.2", "values": []}
# constructed *** Booting Zephyr OS build v4.4.2 *** ⇒ {"rule": "plain", "level": "info", "message": "*** Booting Zephyr OS build v4.4.2 ***", "values": []}
limit set to 2.0 A ⇒ {"rule": "plain", "level": "info", "message": "limit set to 2.0 A", "values": []}
seq=42 ⇒ {"rule": "plain+kv", "level": "info", "message": "seq=42"}
# log_output_test.c expectations without the level flag
[00:00:01.000,000] domain/src: test ⇒ {"rule": "plain", "level": "info", "message": "[00:00:01.000,000] domain/src: test"}
[1970-01-01 00:00:01.000,000] domain/src: test ⇒ {"rule": "plain", "level": "info", "message": "[1970-01-01 00:00:01.000,000] domain/src: test"}
# constructed [00:00:00.106,051] <INF> main: x ⇒ {"rule": "plain", "level": "info", "message": "[00:00:00.106,051] <INF> main: x"}
# constructed [00:00:00.106,051]<inf> main: x ⇒ {"rule": "plain", "level": "info", "message": "[00:00:00.106,051]<inf> main: x"}
# constructed [00:0:00.106,051] <inf> main: x ⇒ {"rule": "plain", "level": "info", "message": "[00:0:00.106,051] <inf> main: x"}
# constructed [00:00:00.106] <inf> main: x ⇒ {"rule": "plain", "level": "info", "message": "[00:00:00.106] <inf> main: x"}
# constructed [00:00:00.106,051] <inf> main:x ⇒ {"rule": "plain", "level": "info", "message": "[00:00:00.106,051] <inf> main:x"}
# constructed [1970-01-01 00:00:01.000] <err> main: x ⇒ {"rule": "plain", "level": "info", "message": "[1970-01-01 00:00:01.000] <err> main: x"}
# constructed [2024-05-01T10:00:00,000000] <inf> m: x ⇒ {"rule": "plain", "level": "info", "message": "[2024-05-01T10:00:00,000000] <inf> m: x"}
# log_output.c ids_print() prints every module's name and a colon after the level
# constructed [00:00:00.500,000] <inf> 42 items left ⇒ {"rule": "plain", "level": "info", "name": "", "message": "[00:00:00.500,000] <inf> 42 items left"}
