nix_compat/log/
mod.rs

1//! Contains types Nix uses for its logging, visible in the "internal-json" log
2//! messages as well as in nix-daemon communication.
3
4use serde::{Deserialize, Serialize};
5use tracing::warn;
6
7/// Every "internal-json" log line emitted by Nix has this prefix.
8pub const AT_NIX_PREFIX: &str = "@nix ";
9
10/// The different verbosity levels Nix distinguishes.
11#[derive(
12    Clone,
13    Debug,
14    Eq,
15    PartialEq,
16    Serialize,
17    Deserialize,
18    num_enum::TryFromPrimitive,
19    num_enum::IntoPrimitive,
20    Default,
21)]
22#[serde(try_from = "u64", into = "u64")]
23#[cfg_attr(
24    feature = "daemon",
25    derive(nix_compat_derive::NixDeserialize, nix_compat_derive::NixSerialize),
26    nix(try_from = "u64", into = "u64")
27)]
28#[repr(u64)]
29pub enum VerbosityLevel {
30    #[default]
31    Error = 0,
32    Warn = 1,
33    Notice = 2,
34    Info = 3,
35    Talkative = 4,
36    Chatty = 5,
37    Debug = 6,
38    Vomit = 7,
39}
40
41impl std::fmt::Display for VerbosityLevel {
42    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
43        write!(
44            f,
45            "{}",
46            match self {
47                VerbosityLevel::Error => "error",
48                VerbosityLevel::Warn => "warn",
49                VerbosityLevel::Notice => "notice",
50                VerbosityLevel::Info => "info",
51                VerbosityLevel::Talkative => "talkative",
52                VerbosityLevel::Chatty => "chatty",
53                VerbosityLevel::Debug => "debug",
54                VerbosityLevel::Vomit => "vomit",
55            }
56        )
57    }
58}
59
60/// The different types of log messages Nix' `internal-json` format can
61/// represent.
62#[derive(Clone, Debug, Eq, PartialEq, Serialize, Deserialize)]
63#[serde(tag = "action" /*, deny_unknown_fields */)]
64// TODO: deny_unknown_fields doesn't seem to work in the testcases below
65pub enum LogMessage<'a> {
66    #[serde(rename = "start")]
67    Start {
68        #[serde(skip_serializing_if = "Option::is_none")]
69        fields: Option<Vec<Field<'a>>>,
70        id: u64,
71        level: VerbosityLevel,
72        parent: u64,
73        text: std::borrow::Cow<'a, str>,
74        r#type: ActivityType,
75    },
76
77    #[serde(rename = "stop")]
78    Stop { id: u64 },
79
80    #[serde(rename = "result")]
81    Result {
82        fields: Vec<Field<'a>>,
83        id: u64,
84        r#type: ResultType,
85    },
86
87    // FUTUREWORK: there sometimes seems to be column/file/line fields set to null, and a raw_msg field,
88    // see msg_with_raw_msg testcase. These should be represented.
89    #[serde(rename = "msg")]
90    Msg {
91        level: VerbosityLevel,
92        msg: std::borrow::Cow<'a, str>,
93    },
94
95    // Log lines like these are sent by nixpkgs stdenv, present in `nix log` outputs of individual builds.
96    // They are also interpreted by Nix to re-emit [Self::Result]-style messages.
97    #[serde(rename = "setPhase")]
98    SetPhase { phase: &'a str },
99}
100
101fn serialize_bytes_as_string<S>(b: &[u8], serializer: S) -> Result<S::Ok, S::Error>
102where
103    S: serde::Serializer,
104{
105    match std::str::from_utf8(b) {
106        Ok(s) => serializer.serialize_str(s),
107        Err(_) => {
108            warn!("encountered invalid utf-8 in JSON");
109            serializer.serialize_bytes(b)
110        }
111    }
112}
113
114/// Fields in a log message can be either ints or strings.
115/// Sometimes, Nix also uses invalid UTF-8 in here, so we use BStr.
116#[derive(Clone, Debug, Eq, PartialEq, Deserialize, Serialize)]
117#[serde(untagged)]
118pub enum Field<'a> {
119    Int(u64),
120    String(#[serde(serialize_with = "serialize_bytes_as_string")] std::borrow::Cow<'a, [u8]>),
121}
122
123#[derive(
124    Clone,
125    Debug,
126    Eq,
127    PartialEq,
128    Serialize,
129    Deserialize,
130    num_enum::TryFromPrimitive,
131    num_enum::IntoPrimitive,
132)]
133#[serde(try_from = "u8", into = "u8")]
134#[repr(u8)]
135pub enum ActivityType {
136    Unknown = 0,
137    CopyPath = 100,
138    FileTransfer = 101,
139    Realise = 102,
140    CopyPaths = 103,
141    Builds = 104,
142    Build = 105,
143    OptimiseStore = 106,
144    VerifyPaths = 107,
145    Substitute = 108,
146    QueryPathInfo = 109,
147    PostBuildHook = 110,
148    BuildWaiting = 111,
149    FetchTree = 112,
150}
151
152impl std::fmt::Display for ActivityType {
153    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
154        write!(
155            f,
156            "{}",
157            match self {
158                ActivityType::Unknown => "unknown",
159                ActivityType::CopyPath => "copy-path",
160                ActivityType::FileTransfer => "file-transfer",
161                ActivityType::Realise => "realise",
162                ActivityType::CopyPaths => "copy-paths",
163                ActivityType::Builds => "builds",
164                ActivityType::Build => "build",
165                ActivityType::OptimiseStore => "optimise-store",
166                ActivityType::VerifyPaths => "verify-paths",
167                ActivityType::Substitute => "substitute",
168                ActivityType::QueryPathInfo => "query-path-info",
169                ActivityType::PostBuildHook => "post-build-hook",
170                ActivityType::BuildWaiting => "build-waiting",
171                ActivityType::FetchTree => "fetch-tree",
172            }
173        )
174    }
175}
176
177#[derive(
178    Clone,
179    Debug,
180    Eq,
181    PartialEq,
182    Serialize,
183    Deserialize,
184    num_enum::TryFromPrimitive,
185    num_enum::IntoPrimitive,
186)]
187#[serde(try_from = "u8", into = "u8")]
188#[repr(u8)]
189pub enum ResultType {
190    FileLinked = 100,
191    BuildLogLine = 101,
192    UntrustedPath = 102,
193    CorruptedPath = 103,
194    SetPhase = 104,
195    Progress = 105,
196    SetExpected = 106,
197    PostBuildLogLine = 107,
198    FetchStatus = 108,
199}
200
201impl<'a> LogMessage<'a> {
202    /// Parses a given log message string into a [LogMessage].
203    pub fn from_json_str(s: &'a str) -> Result<Self, Error> {
204        let s = s.strip_prefix(AT_NIX_PREFIX).ok_or(Error::MissingPrefix)?;
205
206        Ok(serde_json::from_str(s)?)
207    }
208}
209
210impl std::fmt::Display for LogMessage<'_> {
211    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
212        write!(
213            f,
214            "{AT_NIX_PREFIX}{}",
215            serde_json::to_string(self).expect("Failed to serialize LogMessage")
216        )
217    }
218}
219
220#[derive(Debug, thiserror::Error)]
221pub enum Error {
222    #[error("Missing @nix prefix")]
223    MissingPrefix,
224
225    #[error("Failed to deserialize: {0}")]
226    FailedDeserialize(#[from] serde_json::Error),
227}
228
229#[cfg(test)]
230// prevent assert_matches! from complaining about expected_message being unused,
231// while it *is* compared.
232#[allow(unused_variables)]
233mod test {
234    use super::{ActivityType, Field, LogMessage, ResultType, VerbosityLevel};
235    use rstest::rstest;
236
237    #[test]
238    fn verbosity_level() {
239        assert_eq!(
240            VerbosityLevel::try_from(0).expect("must succeed"),
241            VerbosityLevel::Error
242        );
243        assert_eq!(VerbosityLevel::default(), VerbosityLevel::Error);
244
245        // Nix can be caused to send a verbosity level larger than itself knows about,
246        // (by passing too many -v arguments) but we reject this.
247        VerbosityLevel::try_from(42).expect_err("must fail parsing");
248    }
249
250    #[rstest]
251    #[case::start(
252        r#"@nix {"action":"start","id":1264799149195466,"level":5,"parent":0,"text":"copying '/nix/store/rfqxfljma55x8ybmyg07crnarvqx62sr-nixpkgs-src/pkgs/development/compilers/llvm/18/llvm/lit-shell-script-runner-set-dyld-library-path.patch' to the store","type":0}"#,
253        LogMessage::Start {
254            fields: None,
255            id: 1264799149195466,
256            level: VerbosityLevel::Chatty,
257            parent: 0,
258            text: "copying '/nix/store/rfqxfljma55x8ybmyg07crnarvqx62sr-nixpkgs-src/pkgs/development/compilers/llvm/18/llvm/lit-shell-script-runner-set-dyld-library-path.patch' to the store".into(),
259            r#type: ActivityType::Unknown,
260        },
261        true
262    )]
263    #[case::stop(
264        r#"@nix {"action":"stop","id":1264799149195466}"#,
265        LogMessage::Stop {
266            id: 1264799149195466,
267        },
268        true
269    )]
270    #[case::start_with_fields(
271        r#"@nix {"action":"start","fields":["/nix/store/j3hy9syhvyqhghb13vk1433h81q50wcc-rust_tvix-store-0.1.0-linked","https://cache.nixos.org"],"id":1289035649646595,"level":4,"parent":0,"text":"querying info about '/nix/store/j3hy9syhvyqhghb13vk1433h81q50wcc-rust_tvix-store-0.1.0-linked' on 'https://cache.nixos.org'","type":109}"#,
272        LogMessage::Start { fields: Some(vec![Field::String(b"/nix/store/j3hy9syhvyqhghb13vk1433h81q50wcc-rust_tvix-store-0.1.0-linked".into()),Field::String(b"https://cache.nixos.org".into())]), id: 1289035649646595, level: VerbosityLevel::Talkative, parent: 0, text: "querying info about '/nix/store/j3hy9syhvyqhghb13vk1433h81q50wcc-rust_tvix-store-0.1.0-linked' on 'https://cache.nixos.org'".into(), r#type: ActivityType::QueryPathInfo },
273        true
274    )]
275    #[case::result(
276        r#"@nix {"action":"result","fields":[0,0,0,0],"id":1289035649646594,"type":105}"#,
277        LogMessage::Result {
278            id: 1289035649646594,
279            fields: vec![Field::Int(0), Field::Int(0), Field::Int(0), Field::Int(0)],
280            r#type: ResultType::Progress
281        },
282        true
283    )]
284    #[case::msg(
285        r#"@nix {"action":"msg","level":3,"msg":"  /nix/store/zdxxlb3p1vaq1dgh6vfc7c1c52ry4n2f-rust_opentelemetry-semantic-conventions-0.27.0.drv"}"#,
286        LogMessage::Msg { level: VerbosityLevel::Info, msg: "  /nix/store/zdxxlb3p1vaq1dgh6vfc7c1c52ry4n2f-rust_opentelemetry-semantic-conventions-0.27.0.drv".into() },
287        true
288    )]
289    #[case::msg_with_raw_msg(
290        r#"@nix {"action":"msg","column":null,"file":null,"level":0,"line":null,"msg":"\u001b[31;1merror:\u001b[0m interrupted by the user","raw_msg":"interrupted by the user"}"#,
291        LogMessage::Msg {
292            level: VerbosityLevel::Error,
293            msg: "\u{001b}[31;1merror:\u{001b}[0m interrupted by the user".into(),
294        },
295        // FUTUREWORK: represent file/column/line/raw_msg and drop the expected_roundtrip arg alltogether
296        false
297    )]
298    #[case::result_with_fields_int(
299        r#"@nix {"action":"result","fields":[101,146944],"id":15116785938335501,"type":106}"#,
300        LogMessage::Result { fields: vec![
301            Field::Int(101),
302            Field::Int(146944),
303        ], id: 15116785938335501, r#type: ResultType::SetExpected },
304        true
305    )]
306    #[case::set_phase(
307        r#"@nix {"action":"setPhase","phase":"unpackPhase"}"#,
308        LogMessage::SetPhase {
309            phase: "unpackPhase"
310        },
311        true
312    )]
313    #[case::set_phase_result(
314        r#"@nix {"action":"result","fields":["unpackPhase"],"id":418969764757508,"type":104}"#,
315        LogMessage::Result {
316            fields: vec![Field::String(b"unpackPhase".into())],
317            id: 418969764757508,
318            r#type: ResultType::SetPhase,
319        },
320        true
321    )]
322    fn serialize_deserialize(
323        #[case] input_str: &str,
324        #[case] expected_logmessage: LogMessage,
325        #[case] expected_roundtrip: bool,
326    ) {
327        pretty_assertions::assert_matches!(
328            LogMessage::from_json_str(input_str),
329            expected_logmessage,
330            "Expected from_str to return the expected LogMessage"
331        );
332
333        if expected_roundtrip {
334            assert_eq!(
335                input_str,
336                expected_logmessage.to_string(),
337                "Expected LogMessage to roundtrip to input_str"
338            );
339        }
340    }
341}
nix_compat/log/mod.rs

nix_compat/log/
mod.rs
