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

nix_compat/log/
mod.rs
