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

nix_compat/log/
mod.rs
