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    use std::borrow::Cow;
234
235    use super::VerbosityLevel;
236    #[cfg(feature = "serde")]
237    use super::{ActivityType, Field, LogMessage, ResultType};
238    #[cfg(feature = "serde")]
239    use rstest::rstest;
240
241    #[test]
242    fn verbosity_level() {
243        assert_eq!(
244            VerbosityLevel::try_from(0).expect("must succeed"),
245            VerbosityLevel::Error
246        );
247        assert_eq!(VerbosityLevel::default(), VerbosityLevel::Error);
248
249        // Nix can be caused to send a verbosity level larger than itself knows about,
250        // (by passing too many -v arguments) but we reject this.
251        VerbosityLevel::try_from(42).expect_err("must fail parsing");
252    }
253
254    #[cfg(feature = "serde")]
255    #[rstest]
256    #[case::start(
257        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}"#,
258        LogMessage::Start {
259            fields: None,
260            id: 1264799149195466,
261            level: VerbosityLevel::Chatty,
262            parent: 0,
263            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(),
264            r#type: ActivityType::Unknown,
265        },
266        true
267    )]
268    #[case::stop(
269        r#"@nix {"action":"stop","id":1264799149195466}"#,
270        LogMessage::Stop {
271            id: 1264799149195466,
272        },
273        true
274    )]
275    #[case::start_with_fields(
276        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}"#,
277        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 },
278        true
279    )]
280    #[case::result(
281        r#"@nix {"action":"result","fields":[0,0,0,0],"id":1289035649646594,"type":105}"#,
282        LogMessage::Result {
283            id: 1289035649646594,
284            fields: vec![Field::Int(0), Field::Int(0), Field::Int(0), Field::Int(0)],
285            r#type: ResultType::Progress
286        },
287        true
288    )]
289    #[case::msg(
290        r#"@nix {"action":"msg","level":3,"msg":"  /nix/store/zdxxlb3p1vaq1dgh6vfc7c1c52ry4n2f-rust_opentelemetry-semantic-conventions-0.27.0.drv"}"#,
291        LogMessage::Msg { level: VerbosityLevel::Info, msg: "  /nix/store/zdxxlb3p1vaq1dgh6vfc7c1c52ry4n2f-rust_opentelemetry-semantic-conventions-0.27.0.drv".into() },
292        true
293    )]
294    #[case::msg_with_raw_msg(
295        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"}"#,
296        LogMessage::Msg {
297            level: VerbosityLevel::Error,
298            msg: "\u{001b}[31;1merror:\u{001b}[0m interrupted by the user".into(),
299        },
300        // FUTUREWORK: represent file/column/line/raw_msg and drop the expected_roundtrip arg alltogether
301        false
302    )]
303    #[case::result_with_fields_int(
304        r#"@nix {"action":"result","fields":[101,146944],"id":15116785938335501,"type":106}"#,
305        LogMessage::Result { fields: vec![
306            Field::Int(101),
307            Field::Int(146944),
308        ], id: 15116785938335501, r#type: ResultType::SetExpected },
309        true
310    )]
311    #[case::set_phase(
312        r#"@nix {"action":"setPhase","phase":"unpackPhase"}"#,
313        LogMessage::SetPhase {
314            phase: "unpackPhase"
315        },
316        true
317    )]
318    #[case::set_phase_result(
319        r#"@nix {"action":"result","fields":["unpackPhase"],"id":418969764757508,"type":104}"#,
320        LogMessage::Result {
321            fields: vec![Field::String(b"unpackPhase".into())],
322            id: 418969764757508,
323            r#type: ResultType::SetPhase,
324        },
325        true
326    )]
327    fn serialize_deserialize(
328        #[case] input_str: &str,
329        #[case] expected_logmessage: LogMessage,
330        #[case] expected_roundtrip: bool,
331    ) {
332        pretty_assertions::assert_matches!(
333            LogMessage::from_json_str(input_str),
334            expected_logmessage,
335            "Expected from_str to return the expected LogMessage"
336        );
337
338        if expected_roundtrip {
339            assert_eq!(
340                input_str,
341                expected_logmessage.to_string(),
342                "Expected LogMessage to roundtrip to input_str"
343            );
344        }
345    }
346
347    #[cfg(feature = "serde")]
348    #[rstest]
349    #[case::numeric("0", Field::Int(0))]
350    #[case::string(r#""test!""#, Field::String(Cow::Borrowed(b"test!")))]
351    // This one is actually owned, but we check for Eq here and it doesn't care.
352    // See test_string_fields_cow below for checking CoW.
353    #[case::string_escaped(r#""test\\a""#, Field::String(Cow::Borrowed(b"test\\a")))]
354    fn test_fields(#[case] input_str: &str, #[case] expected_output: Field) {
355        assert_eq!(
356            expected_output,
357            serde_json::from_str::<Field>(input_str).expect("must deserialize")
358        );
359    }
360
361    #[cfg(feature = "serde")]
362    #[test]
363    fn test_string_fields_cow() {
364        use pretty_assertions::assert_matches;
365
366        assert_matches!(
367            serde_json::from_str::<Field>(r#""test!""#).expect("must deserialize"),
368            Field::String(Cow::Borrowed(_))
369        );
370        assert_matches!(
371            serde_json::from_str::<Field>(r#""test\\a""#).expect("must deserialize"),
372            Field::String(Cow::Owned(_))
373        );
374    }
375}
nix_compat/log/mod.rs

nix_compat/log/
mod.rs
