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(feature = "serde", serde(serialize_with = "serialize_bytes_as_string"))]
122        std::borrow::Cow<'a, [u8]>,
123    ),
124}
125
126#[derive(Clone, Debug, Eq, PartialEq, num_enum::TryFromPrimitive, num_enum::IntoPrimitive)]
127#[cfg_attr(
128    feature = "serde",
129    derive(Serialize, Deserialize),
130    serde(try_from = "u8", into = "u8")
131)]
132#[repr(u8)]
133pub enum ActivityType {
134    Unknown = 0,
135    CopyPath = 100,
136    FileTransfer = 101,
137    Realise = 102,
138    CopyPaths = 103,
139    Builds = 104,
140    Build = 105,
141    OptimiseStore = 106,
142    VerifyPaths = 107,
143    Substitute = 108,
144    QueryPathInfo = 109,
145    PostBuildHook = 110,
146    BuildWaiting = 111,
147    FetchTree = 112,
148}
149
150impl std::fmt::Display for ActivityType {
151    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
152        write!(
153            f,
154            "{}",
155            match self {
156                ActivityType::Unknown => "unknown",
157                ActivityType::CopyPath => "copy-path",
158                ActivityType::FileTransfer => "file-transfer",
159                ActivityType::Realise => "realise",
160                ActivityType::CopyPaths => "copy-paths",
161                ActivityType::Builds => "builds",
162                ActivityType::Build => "build",
163                ActivityType::OptimiseStore => "optimise-store",
164                ActivityType::VerifyPaths => "verify-paths",
165                ActivityType::Substitute => "substitute",
166                ActivityType::QueryPathInfo => "query-path-info",
167                ActivityType::PostBuildHook => "post-build-hook",
168                ActivityType::BuildWaiting => "build-waiting",
169                ActivityType::FetchTree => "fetch-tree",
170            }
171        )
172    }
173}
174
175#[derive(Clone, Debug, Eq, PartialEq, num_enum::TryFromPrimitive, num_enum::IntoPrimitive)]
176#[cfg_attr(
177    feature = "serde",
178    derive(Serialize, Deserialize),
179    serde(try_from = "u8", into = "u8")
180)]
181#[repr(u8)]
182pub enum ResultType {
183    FileLinked = 100,
184    BuildLogLine = 101,
185    UntrustedPath = 102,
186    CorruptedPath = 103,
187    SetPhase = 104,
188    Progress = 105,
189    SetExpected = 106,
190    PostBuildLogLine = 107,
191    FetchStatus = 108,
192}
193
194impl<'a> LogMessage<'a> {
195    /// Parses a given log message string into a [LogMessage].
196    #[cfg(feature = "serde")]
197    pub fn from_json_str(s: &'a str) -> Result<Self, Error> {
198        let s = s.strip_prefix(AT_NIX_PREFIX).ok_or(Error::MissingPrefix)?;
199
200        Ok(serde_json::from_str(s)?)
201    }
202}
203
204#[cfg(feature = "serde")]
205impl std::fmt::Display for LogMessage<'_> {
206    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
207        write!(
208            f,
209            "{AT_NIX_PREFIX}{}",
210            serde_json::to_string(self).expect("Failed to serialize LogMessage")
211        )
212    }
213}
214
215#[cfg(feature = "serde")]
216#[derive(Debug, thiserror::Error)]
217pub enum Error {
218    #[error("Missing @nix prefix")]
219    MissingPrefix,
220
221    #[error("Failed to deserialize: {0}")]
222    FailedDeserialize(#[from] serde_json::Error),
223}
224
225#[cfg(test)]
226// prevent assert_matches! from complaining about expected_message being unused,
227// while it *is* compared.
228#[allow(unused_variables)]
229mod test {
230    use super::VerbosityLevel;
231    #[cfg(feature = "serde")]
232    use super::{ActivityType, Field, LogMessage, ResultType};
233    #[cfg(feature = "serde")]
234    use rstest::rstest;
235
236    #[test]
237    fn verbosity_level() {
238        assert_eq!(
239            VerbosityLevel::try_from(0).expect("must succeed"),
240            VerbosityLevel::Error
241        );
242        assert_eq!(VerbosityLevel::default(), VerbosityLevel::Error);
243
244        // Nix can be caused to send a verbosity level larger than itself knows about,
245        // (by passing too many -v arguments) but we reject this.
246        VerbosityLevel::try_from(42).expect_err("must fail parsing");
247    }
248
249    #[cfg(feature = "serde")]
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
