tracing-journald not output all the info?

[mamcx]

Bug Report

Version

tracing= {version="0.1.32", features = ["log"] }
tracing-futures = "0.2.5"
tracing-appender = "0.2.2"
tracing-journald = "0.2.4"
tracing-subscriber = {version="0.3.10", features = ["env-filter", "json"] }

Platform

Linux 4.15.0-175-generic #184-Ubuntu SMP Thu Mar 24 17:48:36 UTC 2022 x86_64 x86_64 x86_64 GNU/Linux
(Running also on nixos)

Description

I try to setup journald tracing so i can replace the use of json. When comparing the info with just tracing-journald VS what I have before with stdout/json, I see that is missing a lot of info:

With stdout and pretty:

  2022-04-06T16:06:53.021443Z DEBUG iron_age_db::pg: sql: "SELECT *, COUNT(*) OVER() AS _full_count FROM customer_menu WHERE is_active = :is_active AND is_active_adress = :is_active_adress ORDER BY customer_code ASC LIMIT 100;", params: Named({":is_active": Bool(true), ":is_active_adress": Bool(true)})
    at /home/circleci/IronAge/db/src/pg.rs:225
    in iron_age_db::pg::SELECT ROWS with self: PG:BestSeller4/appnet
    in server::admin::LIST
127.0.0.1 "GET /manager/pick/customer/OrderCreate/ HTTP/1.1" 200 16822 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/100.0.4896.75 Safari/537.36" 0.138648
  2022-04-06T16:06:53.132655Z  INFO actix_web::middleware::logger: 127.0.0.1 "GET /manager/pick/customer/OrderCreate/ HTTP/1.1" 200 16822 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/100.0.4896.75 Safari/537.36" 0.141218
    at /home/circleci/.cargo/registry/src/github.com-1ecc6299db9ec823/actix-web-4.0.1/src/middleware/logger.rs:351
error handling /static/css/company/appnet.css/: No such file or directory (os error 2)

With just journald:

127.0.0.1 "GET /?XDEBUG_SESSION_START=phpstorm HTTP/1.1" 500 3746 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.108 Safari/537.36" 0.040514
Login NEW
CheckStoreLoginMiddleware
Login STORE OK
Login NEW
[server/src/store.rs:24] &t = Anom(
    "01FZZV0SWDM37YV1M46CNCG53K",
)
127.0.0.1 "GET / HTTP/1.1" 500 3746 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:47.0) Gecko/20100101 Firefox/47.0" 0.010368
127.0.0.1 "GET /static/img/favicon/apple-touch-icon.png HTTP/1.1" 200 2880 "http://45.77.117.138:80/static/img/favicon/apple-touch-icon.png" "Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.132 Safari/537.36 QIHU 360SE" 0.006545

Things like "Login NEW" have a lot of context I don't see.

[saschagrunert]

Are we somehow stripping the scope from the journald logger? I see that it mainly logs the messages rather than the full context.

[hawkw]

When using tracing-journald, the span context and additional fields of an event are recorded using journald's structured fields. I believe these are not displayed by default in journalctl, which only displays the MESSAGE field, but they are recorded, and I believe journalctl can be instructed to display additional information.

cc @Ralith perhaps this could be made clearer in the documentation? We may want to provide additional instructions on how to get journalctl to display these fields?

[Ralith]

This behavior is indeed the entire point of tracing-journald. See man journalctl. The -o verbose, -o json, and --output-fields=... options may be of particular interest.

[saschagrunert]

Thank you for the clarification, this helps a lot!