diff --git a/tvix/Cargo.nix b/tvix/Cargo.nix index 3f96e76fd..1e152e762 100644 --- a/tvix/Cargo.nix +++ b/tvix/Cargo.nix @@ -8285,6 +8285,7 @@ rec { { name = "pretty_assertions"; packageId = "pretty_assertions"; + features = [ "unstable" ]; } { name = "proptest"; @@ -8296,10 +8297,6 @@ rec { name = "rstest"; packageId = "rstest"; } - { - name = "serde_json"; - packageId = "serde_json"; - } { name = "smol_str"; packageId = "smol_str"; @@ -9984,7 +9981,7 @@ rec { features = { "default" = [ "std" ]; }; - resolvedDefaultFeatures = [ "default" "std" ]; + resolvedDefaultFeatures = [ "default" "std" "unstable" ]; }; "prettyplease" = rec { crateName = "prettyplease"; diff --git a/tvix/nix-compat/Cargo.toml b/tvix/nix-compat/Cargo.toml index 822c66d21..261438b7e 100644 --- a/tvix/nix-compat/Cargo.toml +++ b/tvix/nix-compat/Cargo.toml @@ -48,10 +48,9 @@ futures.workspace = true hex-literal.workspace = true mimalloc.workspace = true mockall = "0.13.1" -pretty_assertions.workspace = true +pretty_assertions = { workspace = true, features = ["unstable"] } proptest = { workspace = true, features = ["std", "alloc", "tempfile"] } rstest.workspace = true -serde_json.workspace = true smol_str.workspace = true tokio-test.workspace = true zstd.workspace = true diff --git a/tvix/nix-compat/src/lib.rs b/tvix/nix-compat/src/lib.rs index 4c327fa45..4d2d5931e 100644 --- a/tvix/nix-compat/src/lib.rs +++ b/tvix/nix-compat/src/lib.rs @@ -2,6 +2,7 @@ extern crate self as nix_compat; pub(crate) mod aterm; pub mod derivation; +pub mod log; pub mod nar; pub mod narinfo; pub mod nix_http; diff --git a/tvix/nix-compat/src/log/mod.rs b/tvix/nix-compat/src/log/mod.rs new file mode 100644 index 000000000..45e780a4d --- /dev/null +++ b/tvix/nix-compat/src/log/mod.rs @@ -0,0 +1,341 @@ +//! Contains types Nix uses for its logging, visible in the "internal-json" log +//! messages as well as in nix-daemon communication. + +use serde::{Deserialize, Serialize}; +use tracing::warn; + +/// Every "internal-json" log line emitted by Nix has this prefix. +pub const AT_NIX_PREFIX: &str = "@nix "; + +/// The different verbosity levels Nix distinguishes. +#[derive( + Clone, + Debug, + Eq, + PartialEq, + Serialize, + Deserialize, + num_enum::TryFromPrimitive, + num_enum::IntoPrimitive, + Default, +)] +#[serde(try_from = "u64", into = "u64")] +#[cfg_attr( + feature = "daemon", + derive(nix_compat_derive::NixDeserialize, nix_compat_derive::NixSerialize), + nix(try_from = "u64", into = "u64") +)] +#[repr(u64)] +pub enum VerbosityLevel { + #[default] + Error = 0, + Warn = 1, + Notice = 2, + Info = 3, + Talkative = 4, + Chatty = 5, + Debug = 6, + Vomit = 7, +} + +impl std::fmt::Display for VerbosityLevel { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!( + f, + "{}", + match self { + VerbosityLevel::Error => "error", + VerbosityLevel::Warn => "warn", + VerbosityLevel::Notice => "notice", + VerbosityLevel::Info => "info", + VerbosityLevel::Talkative => "talkative", + VerbosityLevel::Chatty => "chatty", + VerbosityLevel::Debug => "debug", + VerbosityLevel::Vomit => "vomit", + } + ) + } +} + +/// The different types of log messages Nix' `internal-json` format can +/// represent. +#[derive(Clone, Debug, Eq, PartialEq, Serialize, Deserialize)] +#[serde(tag = "action" /*, deny_unknown_fields */)] +// TODO: deny_unknown_fields doesn't seem to work in the testcases below +pub enum LogMessage<'a> { + #[serde(rename = "start")] + Start { + #[serde(skip_serializing_if = "Option::is_none")] + fields: Option>>, + id: u64, + level: VerbosityLevel, + parent: u64, + text: std::borrow::Cow<'a, str>, + r#type: ActivityType, + }, + + #[serde(rename = "stop")] + Stop { id: u64 }, + + #[serde(rename = "result")] + Result { + fields: Vec>, + id: u64, + r#type: ResultType, + }, + + // FUTUREWORK: there sometimes seems to be column/file/line fields set to null, and a raw_msg field, + // see msg_with_raw_msg testcase. These should be represented. + #[serde(rename = "msg")] + Msg { + level: VerbosityLevel, + msg: std::borrow::Cow<'a, str>, + }, + + // Log lines like these are sent by nixpkgs stdenv, present in `nix log` outputs of individual builds. + // They are also interpreted by Nix to re-emit [Self::Result]-style messages. + #[serde(rename = "setPhase")] + SetPhase { phase: &'a str }, +} + +fn serialize_bytes_as_string(b: &[u8], serializer: S) -> Result +where + S: serde::Serializer, +{ + match std::str::from_utf8(b) { + Ok(s) => serializer.serialize_str(s), + Err(_) => { + warn!("encountered invalid utf-8 in JSON"); + serializer.serialize_bytes(b) + } + } +} + +/// Fields in a log message can be either ints or strings. +/// Sometimes, Nix also uses invalid UTF-8 in here, so we use BStr. +#[derive(Clone, Debug, Eq, PartialEq, Deserialize, Serialize)] +#[serde(untagged)] +pub enum Field<'a> { + Int(u64), + String(#[serde(serialize_with = "serialize_bytes_as_string")] std::borrow::Cow<'a, [u8]>), +} + +#[derive( + Clone, + Debug, + Eq, + PartialEq, + Serialize, + Deserialize, + num_enum::TryFromPrimitive, + num_enum::IntoPrimitive, +)] +#[serde(try_from = "u8", into = "u8")] +#[repr(u8)] +pub enum ActivityType { + Unknown = 0, + CopyPath = 100, + FileTransfer = 101, + Realise = 102, + CopyPaths = 103, + Builds = 104, + Build = 105, + OptimiseStore = 106, + VerifyPaths = 107, + Substitute = 108, + QueryPathInfo = 109, + PostBuildHook = 110, + BuildWaiting = 111, + FetchTree = 112, +} + +impl std::fmt::Display for ActivityType { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!( + f, + "{}", + match self { + ActivityType::Unknown => "unknown", + ActivityType::CopyPath => "copy-path", + ActivityType::FileTransfer => "file-transfer", + ActivityType::Realise => "realise", + ActivityType::CopyPaths => "copy-paths", + ActivityType::Builds => "builds", + ActivityType::Build => "build", + ActivityType::OptimiseStore => "optimise-store", + ActivityType::VerifyPaths => "verify-paths", + ActivityType::Substitute => "substitute", + ActivityType::QueryPathInfo => "query-path-info", + ActivityType::PostBuildHook => "post-build-hook", + ActivityType::BuildWaiting => "build-waiting", + ActivityType::FetchTree => "fetch-tree", + } + ) + } +} + +#[derive( + Clone, + Debug, + Eq, + PartialEq, + Serialize, + Deserialize, + num_enum::TryFromPrimitive, + num_enum::IntoPrimitive, +)] +#[serde(try_from = "u8", into = "u8")] +#[repr(u8)] +pub enum ResultType { + FileLinked = 100, + BuildLogLine = 101, + UntrustedPath = 102, + CorruptedPath = 103, + SetPhase = 104, + Progress = 105, + SetExpected = 106, + PostBuildLogLine = 107, + FetchStatus = 108, +} + +impl<'a> LogMessage<'a> { + /// Parses a given log message string into a [LogMessage]. + pub fn from_json_str(s: &'a str) -> Result { + let s = s.strip_prefix(AT_NIX_PREFIX).ok_or(Error::MissingPrefix)?; + + Ok(serde_json::from_str(s)?) + } +} + +impl std::fmt::Display for LogMessage<'_> { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!( + f, + "{AT_NIX_PREFIX}{}", + serde_json::to_string(self).expect("Failed to serialize LogMessage") + ) + } +} + +#[derive(Debug, thiserror::Error)] +pub enum Error { + #[error("Missing @nix prefix")] + MissingPrefix, + + #[error("Failed to deserialize: {0}")] + FailedDeserialize(#[from] serde_json::Error), +} + +#[cfg(test)] +// prevent assert_matches! from complaining about expected_message being unused, +// while it *is* compared. +#[allow(unused_variables)] +mod test { + use super::{ActivityType, Field, LogMessage, ResultType, VerbosityLevel}; + use rstest::rstest; + + #[test] + fn verbosity_level() { + assert_eq!( + VerbosityLevel::try_from(0).expect("must succeed"), + VerbosityLevel::Error + ); + assert_eq!(VerbosityLevel::default(), VerbosityLevel::Error); + + // Nix can be caused to send a verbosity level larger than itself knows about, + // (by passing too many -v arguments) but we reject this. + VerbosityLevel::try_from(42).expect_err("must fail parsing"); + } + + #[rstest] + #[case::start( + 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}"#, + LogMessage::Start { + fields: None, + id: 1264799149195466, + level: VerbosityLevel::Chatty, + 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".into(), + r#type: ActivityType::Unknown, + }, + true + )] + #[case::stop( + r#"@nix {"action":"stop","id":1264799149195466}"#, + LogMessage::Stop { + id: 1264799149195466, + }, + true + )] + #[case::start_with_fields( + 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}"#, + 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 }, + true + )] + #[case::result( + r#"@nix {"action":"result","fields":[0,0,0,0],"id":1289035649646594,"type":105}"#, + LogMessage::Result { + id: 1289035649646594, + fields: vec![Field::Int(0), Field::Int(0), Field::Int(0), Field::Int(0)], + r#type: ResultType::Progress + }, + true + )] + #[case::msg( + r#"@nix {"action":"msg","level":3,"msg":" /nix/store/zdxxlb3p1vaq1dgh6vfc7c1c52ry4n2f-rust_opentelemetry-semantic-conventions-0.27.0.drv"}"#, + LogMessage::Msg { level: VerbosityLevel::Info, msg: " /nix/store/zdxxlb3p1vaq1dgh6vfc7c1c52ry4n2f-rust_opentelemetry-semantic-conventions-0.27.0.drv".into() }, + true + )] + #[case::msg_with_raw_msg( + 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"}"#, + LogMessage::Msg { + level: VerbosityLevel::Error, + msg: "\u{001b}[31;1merror:\u{001b}[0m interrupted by the user".into(), + }, + // FUTUREWORK: represent file/column/line/raw_msg and drop the expected_roundtrip arg alltogether + false + )] + #[case::result_with_fields_int( + r#"@nix {"action":"result","fields":[101,146944],"id":15116785938335501,"type":106}"#, + LogMessage::Result { fields: vec![ + Field::Int(101), + Field::Int(146944), + ], id: 15116785938335501, r#type: ResultType::SetExpected }, + true + )] + #[case::set_phase( + r#"@nix {"action":"setPhase","phase":"unpackPhase"}"#, + LogMessage::SetPhase { + phase: "unpackPhase" + }, + true + )] + #[case::set_phase_result( + r#"@nix {"action":"result","fields":["unpackPhase"],"id":418969764757508,"type":104}"#, + LogMessage::Result { + fields: vec![Field::String(b"unpackPhase".into())], + id: 418969764757508, + r#type: ResultType::SetPhase, + }, + true + )] + fn serialize_deserialize( + #[case] input_str: &str, + #[case] expected_logmessage: LogMessage, + #[case] expected_roundtrip: bool, + ) { + pretty_assertions::assert_matches!( + LogMessage::from_json_str(input_str), + expected_logmessage, + "Expected from_str to return the expected LogMessage" + ); + + if expected_roundtrip { + assert_eq!( + input_str, + expected_logmessage.to_string(), + "Expected LogMessage to roundtrip to input_str" + ); + } + } +} diff --git a/tvix/nix-compat/src/nix_daemon/worker_protocol.rs b/tvix/nix-compat/src/nix_daemon/worker_protocol.rs index ed49cbd9d..686690f62 100644 --- a/tvix/nix-compat/src/nix_daemon/worker_protocol.rs +++ b/tvix/nix-compat/src/nix_daemon/worker_protocol.rs @@ -5,10 +5,10 @@ use std::{ }; use nix_compat_derive::{NixDeserialize, NixSerialize}; -use num_enum::{FromPrimitive, IntoPrimitive, TryFromPrimitive}; +use num_enum::{IntoPrimitive, TryFromPrimitive}; use tokio::io::{AsyncReadExt, AsyncWriteExt}; -use crate::wire; +use crate::{log::VerbosityLevel, wire}; use crate::wire::ProtocolVersion; @@ -109,26 +109,6 @@ pub enum Operation { AddPermRoot = 47, } -/// Log verbosity. In the Nix wire protocol, the client requests a -/// verbosity level to the daemon, which in turns does not produce any -/// log below this verbosity. -#[derive( - Debug, PartialEq, FromPrimitive, IntoPrimitive, NixDeserialize, NixSerialize, Default, Clone, -)] -#[nix(from = "u64", into = "u64")] -#[repr(u64)] -pub enum Verbosity { - #[default] - LvlError = 0, - LvlWarn = 1, - LvlNotice = 2, - LvlInfo = 3, - LvlTalkative = 4, - LvlChatty = 5, - LvlDebug = 6, - LvlVomit = 7, -} - /// Settings requested by the client. These settings are applied to a /// connection to between the daemon and a client. #[derive(Debug, PartialEq, NixDeserialize, NixSerialize, Default)] @@ -136,7 +116,10 @@ pub struct ClientSettings { pub keep_failed: bool, pub keep_going: bool, pub try_fallback: bool, - pub verbosity: Verbosity, + // In the Nix wire protocol, the client requests a verbosity level + // to the daemon, which in turn does not produce any log below this + // verbosity. + pub verbosity: VerbosityLevel, pub max_build_jobs: u64, pub max_silent_time: u64, pub use_build_hook: bool, diff --git a/users/edef/crunch-v2/Cargo.nix b/users/edef/crunch-v2/Cargo.nix index 8b3e53487..b35646f36 100644 --- a/users/edef/crunch-v2/Cargo.nix +++ b/users/edef/crunch-v2/Cargo.nix @@ -4178,10 +4178,6 @@ rec { name = "mimalloc"; packageId = "mimalloc"; } - { - name = "serde_json"; - packageId = "serde_json"; - } ]; features = { "async" = [ "tokio" ]; diff --git a/users/edef/fetchroots/Cargo.nix b/users/edef/fetchroots/Cargo.nix index b20452c0c..32523e60c 100644 --- a/users/edef/fetchroots/Cargo.nix +++ b/users/edef/fetchroots/Cargo.nix @@ -5580,10 +5580,6 @@ rec { name = "mimalloc"; packageId = "mimalloc"; } - { - name = "serde_json"; - packageId = "serde_json"; - } ]; features = { "async" = [ "tokio" ]; diff --git a/users/edef/narinfo2parquet/Cargo.nix b/users/edef/narinfo2parquet/Cargo.nix index 59ce38fe5..35449dee4 100644 --- a/users/edef/narinfo2parquet/Cargo.nix +++ b/users/edef/narinfo2parquet/Cargo.nix @@ -2904,10 +2904,6 @@ rec { name = "mimalloc"; packageId = "mimalloc"; } - { - name = "serde_json"; - packageId = "serde_json"; - } ]; features = { "async" = [ "tokio" ]; diff --git a/users/edef/weave/Cargo.nix b/users/edef/weave/Cargo.nix index 042a765f4..00cdd85e1 100644 --- a/users/edef/weave/Cargo.nix +++ b/users/edef/weave/Cargo.nix @@ -2987,10 +2987,6 @@ rec { name = "mimalloc"; packageId = "mimalloc"; } - { - name = "serde_json"; - packageId = "serde_json"; - } ]; features = { "async" = [ "tokio" ]; diff --git a/users/picnoir/tvix-daemon/Cargo.lock b/users/picnoir/tvix-daemon/Cargo.lock index ee8045948..a9ea07acc 100644 --- a/users/picnoir/tvix-daemon/Cargo.lock +++ b/users/picnoir/tvix-daemon/Cargo.lock @@ -1,6 +1,6 @@ # This file is automatically @generated by Cargo. # It is not intended for manual editing. -version = 3 +version = 4 [[package]] name = "addr2line" @@ -796,6 +796,7 @@ dependencies = [ "pin-project-lite", "serde", "serde_json", + "serde_repr", "sha2", "thiserror", "tokio", @@ -1084,6 +1085,17 @@ dependencies = [ "serde", ] +[[package]] +name = "serde_repr" +version = "0.1.19" +source = "registry+https://github.com/rust-lang/crates.io-index" +checksum = "6c64451ba24fc7a6a2d60fc75dd9c83c90903b19028d4eff35e88fc1e86564e9" +dependencies = [ + "proc-macro2", + "quote", + "syn", +] + [[package]] name = "serde_urlencoded" version = "0.7.1" @@ -1189,9 +1201,9 @@ checksum = "13c2bddecc57b384dee18652358fb23172facb8a2c51ccc10d74c157bdea3292" [[package]] name = "syn" -version = "2.0.79" +version = "2.0.87" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "89132cd0bf050864e1d38dc3bbc07a0eb8e7530af26344d3d2bbbef83499f590" +checksum = "25aa4ce346d03a6dcd68dd8b4010bcb74e54e62c90c573f394c46eae99aba32d" dependencies = [ "proc-macro2", "quote", @@ -1212,18 +1224,18 @@ checksum = "a7065abeca94b6a8a577f9bd45aa0867a2238b74e8eb67cf10d492bc39351394" [[package]] name = "thiserror" -version = "1.0.64" +version = "2.0.11" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "d50af8abc119fb8bb6dbabcfa89656f46f84aa0ac7688088608076ad2b459a84" +checksum = "d452f284b73e6d76dd36758a0c8684b1d5be31f92b89d07fd5822175732206fc" dependencies = [ "thiserror-impl", ] [[package]] name = "thiserror-impl" -version = "1.0.64" +version = "2.0.11" source = "registry+https://github.com/rust-lang/crates.io-index" -checksum = "08904e7672f5eb876eaaf87e0ce17857500934f4981c4a0ab2b4aa98baac7fc3" +checksum = "26afc1baea8a989337eeb52b6e72a039780ce45c3edfcc9c5b9d112feeb173c2" dependencies = [ "proc-macro2", "quote", diff --git a/users/picnoir/tvix-daemon/Cargo.nix b/users/picnoir/tvix-daemon/Cargo.nix index c465131e3..7f6d40854 100644 --- a/users/picnoir/tvix-daemon/Cargo.nix +++ b/users/picnoir/tvix-daemon/Cargo.nix @@ -2499,6 +2499,10 @@ rec { name = "serde_json"; packageId = "serde_json"; } + { + name = "serde_repr"; + packageId = "serde_repr"; + } { name = "sha2"; packageId = "sha2"; @@ -2527,10 +2531,6 @@ rec { name = "mimalloc"; packageId = "mimalloc"; } - { - name = "serde_json"; - packageId = "serde_json"; - } ]; features = { "async" = [ "tokio" ]; @@ -3304,6 +3304,31 @@ rec { } ]; + }; + "serde_repr" = rec { + crateName = "serde_repr"; + version = "0.1.19"; + edition = "2021"; + sha256 = "1sb4cplc33z86pzlx38234xr141wr3cmviqgssiadisgl8dlar3c"; + procMacro = true; + authors = [ + "David Tolnay " + ]; + dependencies = [ + { + name = "proc-macro2"; + packageId = "proc-macro2"; + } + { + name = "quote"; + packageId = "quote"; + } + { + name = "syn"; + packageId = "syn"; + } + ]; + }; "serde_urlencoded" = rec { crateName = "serde_urlencoded"; @@ -3571,9 +3596,9 @@ rec { }; "syn" = rec { crateName = "syn"; - version = "2.0.79"; + version = "2.0.87"; edition = "2021"; - sha256 = "147mk4sgigmvsb9l8qzj199ygf0fgb0bphwdsghn8205pz82q4w9"; + sha256 = "0bd3mfcswvn4jkrp7ich5kk58kmpph8412yxd36nsfnh8vilrai5"; authors = [ "David Tolnay " ]; @@ -3630,9 +3655,9 @@ rec { }; "thiserror" = rec { crateName = "thiserror"; - version = "1.0.64"; + version = "2.0.11"; edition = "2021"; - sha256 = "114s8lmssxl0c2480s671am88vzlasbaikxbvfv8pyqrq6mzh2nm"; + sha256 = "1z0649rpa8c2smzx129bz4qvxmdihj30r2km6vfpcv9yny2g4lnl"; authors = [ "David Tolnay " ]; @@ -3642,13 +3667,16 @@ rec { packageId = "thiserror-impl"; } ]; - + features = { + "default" = [ "std" ]; + }; + resolvedDefaultFeatures = [ "default" "std" ]; }; "thiserror-impl" = rec { crateName = "thiserror-impl"; - version = "1.0.64"; + version = "2.0.11"; edition = "2021"; - sha256 = "1hvzmjx9iamln854l74qyhs0jl2pg3hhqzpqm9p8gszmf9v4x408"; + sha256 = "1hkkn7p2y4cxbffcrprybkj0qy1rl1r6waxmxqvr764axaxc3br6"; procMacro = true; libName = "thiserror_impl"; authors = [