Merge pull request #134 from NixOS/log-instantiation-failures

Log instantiation failures

nix/ofborg-carnix.nix

@@ -45,7 +45,7 @@ let kernel = buildPlatform.parsed.kernel.name;
     ) [] (builtins.attrNames feat);
 in
 rec {
-  ofborg = f: ofborg_0_1_3 { features = ofborg_0_1_3_features { ofborg_0_1_3 = f; }; };
+  ofborg = f: ofborg_0_1_4 { features = ofborg_0_1_4_features { ofborg_0_1_4 = f; }; };
   aho_corasick_0_5_3_ = { dependencies?[], buildDependencies?[], features?[] }: buildRustCrate {
     crateName = "aho-corasick";
     version = "0.5.3";
@@ -413,9 +413,9 @@ rec {
     sha256 = "1y6qnd9r8ga6y8mvlabdrr73nc8cshjjlzbvnanzyj9b8zzkfwk2";
     inherit dependencies buildDependencies features;
   };
-  ofborg_0_1_3_ = { dependencies?[], buildDependencies?[], features?[] }: buildRustCrate {
+  ofborg_0_1_4_ = { dependencies?[], buildDependencies?[], features?[] }: buildRustCrate {
     crateName = "ofborg";
-    version = "0.1.3";
+    version = "0.1.4";
     authors = [ "Graham Christensen <graham@grahamc.com>" ];
     src = include [ "Cargo.toml" "Cargo.lock" "src" "test-srcs" "build.rs" ] ./../ofborg;
     build = "build.rs";
@@ -1342,10 +1342,10 @@ rec {
     libc_0_2_36.default = true;
     num_cpus_1_8_0.default = (f.num_cpus_1_8_0.default or true);
   }) [ libc_0_2_36_features ];
-  ofborg_0_1_3 = { features?(ofborg_0_1_3_features {}) }: ofborg_0_1_3_ {
+  ofborg_0_1_4 = { features?(ofborg_0_1_4_features {}) }: ofborg_0_1_4_ {
     dependencies = mapFeatures features ([ amqp_0_1_0 either_1_4_0 env_logger_0_4_3 fs2_0_4_3 hubcaps_0_3_16 hyper_0_10_13 hyper_native_tls_0_2_4 log_0_3_8 lru_cache_0_1_1 md5_0_3_6 serde_1_0_27 serde_derive_1_0_27 serde_json_1_0_9 tempfile_2_2_0 uuid_0_4_0 ]);
   };
-  ofborg_0_1_3_features = f: updateFeatures f (rec {
+  ofborg_0_1_4_features = f: updateFeatures f (rec {
     amqp_0_1_0.default = true;
     either_1_4_0.default = true;
     env_logger_0_4_3.default = true;
@@ -1356,7 +1356,7 @@ rec {
     log_0_3_8.default = true;
     lru_cache_0_1_1.default = true;
     md5_0_3_6.default = true;
-    ofborg_0_1_3.default = (f.ofborg_0_1_3.default or true);
+    ofborg_0_1_4.default = (f.ofborg_0_1_4.default or true);
     serde_1_0_27.default = true;
     serde_derive_1_0_27.default = true;
     serde_json_1_0_9.default = true;

ofborg/Cargo.lock

@@ -379,7 +379,7 @@ dependencies = [
 
 [[package]]
 name = "ofborg"
-version = "0.1.2"
+version = "0.1.4"
 dependencies = [
  "amqp 0.1.0 (git+https://github.com/grahamc/rust-amqp.git)",
  "either 1.4.0 (registry+https://github.com/rust-lang/crates.io-index)",

ofborg/Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "ofborg"
-version = "0.1.3"
+version = "0.1.4"
 authors = ["Graham Christensen <graham@grahamc.com>"]
 include = ["Cargo.toml", "Cargo.lock", "src", "test-srcs", "build.rs"]
 build = "build.rs"

ofborg/src/bin/builder.rs

@@ -25,18 +25,16 @@ fn main() {
     let cloner = checkout::cached_cloner(Path::new(&cfg.checkout.root));
     let nix = cfg.nix();
 
-    let full_logs: bool = match &cfg.feedback {
+    if cfg.feedback.full_logs != true {
-        &Some(ref feedback) => feedback.full_logs,
+        warn!("Please define feedback.full_logs in your configuration to true!");
-        &None => {
+        warn!("feedback.full_logs when true will cause the full build log to be sent back");
-            warn!("Please define feedback.full_logs in your configuration to true or false!");
+        warn!("to the server, and be viewable by everyone.");
-            warn!("feedback.full_logs when true will cause the full build log to be sent back");
+        warn!("");
-            warn!("to the server, and be viewable by everyone.");
+        warn!("Builders are no longer allowed to operate with this off");
-            warn!("I strongly encourage everybody turn this on!");
+        warn!("so your builder will no longer start.");
-            false
+        panic!();
-        }
     };
 
-
     let mut session = easyamqp::session_from_config(&cfg.rabbitmq).unwrap();
     let mut channel = session.open_channel(1).unwrap();
     channel.basic_prefetch(1).unwrap();
@@ -53,21 +51,38 @@ fn main() {
         })
         .unwrap();
 
-    channel
+    let queue_name: String;
-        .declare_queue(easyamqp::QueueConfig {
+    if cfg.runner.build_all_jobs != Some(true) {
-            queue: format!("build-inputs-{}", cfg.nix.system.clone()),
+        queue_name = channel
-            passive: false,
+            .declare_queue(easyamqp::QueueConfig {
-            durable: true,
+                queue: format!("build-inputs-{}", cfg.nix.system.clone()),
-            exclusive: false,
+                passive: false,
-            auto_delete: false,
+                durable: true,
-            no_wait: false,
+                exclusive: false,
-            arguments: None,
+                auto_delete: false,
-        })
+                no_wait: false,
-        .unwrap();
+                arguments: None,
+            })
+            .unwrap().queue;
+    } else {
+        warn!("Building all jobs, please don't use this unless you're");
+        warn!("developing and have Graham's permission!");
+        queue_name = channel
+            .declare_queue(easyamqp::QueueConfig {
+                queue: "".to_owned(),
+                passive: false,
+                durable: false,
+                exclusive: true,
+                auto_delete: true,
+                no_wait: false,
+                arguments: None,
+            })
+            .unwrap().queue;
+    }
 
     channel
         .bind_queue(easyamqp::BindQueueConfig {
-            queue: format!("build-inputs-{}", cfg.nix.system.clone()),
+            queue: queue_name.clone(),
             exchange: "build-jobs".to_owned(),
             routing_key: None,
             no_wait: false,
@@ -82,10 +97,9 @@ fn main() {
                 nix,
                 cfg.nix.system.clone(),
                 cfg.runner.identity.clone(),
-                full_logs,
             )),
             easyamqp::ConsumeConfig {
-                queue: format!("build-inputs-{}", cfg.nix.system.clone()),
+                queue: queue_name.clone(),
                 consumer_tag: format!("{}-builder", cfg.whoami()),
                 no_local: false,
                 no_ack: false,
@@ -96,6 +110,7 @@ fn main() {
         )
         .unwrap();
 
+    println!("Fetching jobs from {}", &queue_name);
     channel.start_consuming();
     channel.close(200, "Bye").unwrap();
     println!("Closed the channel");

ofborg/src/config.rs

@@ -15,7 +15,7 @@ use ofborg::acl;
 #[derive(Serialize, Deserialize, Debug)]
 pub struct Config {
     pub runner: RunnerConfig,
-    pub feedback: Option<FeedbackConfig>,
+    pub feedback: FeedbackConfig,
     pub checkout: CheckoutConfig,
     pub nix: NixConfig,
     pub rabbitmq: RabbitMQConfig,
@@ -62,6 +62,14 @@ pub struct RunnerConfig {
     pub repos: Option<Vec<String>>,
     pub trusted_users: Option<Vec<String>>,
     pub known_users: Option<Vec<String>>,
+
+    /// If true, will create its own queue attached to the build job
+    /// exchange. This means that builders with this enabled will
+    /// trigger duplicate replies to the request for this
+    /// architecture.
+    ///
+    /// This should only be turned on for development.
+    pub build_all_jobs: Option<bool>
 }
 
 #[derive(Serialize, Deserialize, Debug)]

ofborg/src/lib.rs

@@ -70,6 +70,19 @@ pub mod ofborg {
     pub use easyamqp;
 
     pub const VERSION: &'static str = env!("CARGO_PKG_VERSION");
+
+    pub fn partition_result<A,B>(results: Vec<Result<A,B>>) -> (Vec<A>, Vec<B>) {
+        let mut ok = Vec::new();
+        let mut err = Vec::new();
+        for result in results.into_iter() {
+            match result {
+                Ok(x) => { ok.push(x); }
+                Err(x) => { err.push(x); }
+            }
+        }
+
+        (ok, err)
+    }
 }
 
 pub fn setup_log() {

ofborg/src/nix.rs

@@ -6,6 +6,9 @@ use std::io::SeekFrom;
 use std::path::Path;
 use std::process::{Command, Stdio};
 use tempfile::tempfile;
+use std::io::BufReader;
+use std::io::BufRead;
+use ofborg::partition_result;
 
 #[derive(Clone, Debug)]
 pub enum Operation {
@@ -102,16 +105,23 @@ impl Nix {
         nixpkgs: &Path,
         file: &str,
         attrs: Vec<String>,
-    ) -> (Vec<String>, Vec<String>) {
+    ) -> (Vec<String>, Vec<(String,Vec<String>)>) {
-        attrs
+        let attr_instantiations: Vec<Result<String, (String, Vec<String>)>> =
+            attrs
             .into_iter()
-            .partition(|attr| {
+            .map(|attr|
-                self.safely_instantiate_attrs(
+                 match self.safely_instantiate_attrs(
-                    nixpkgs,
+                     nixpkgs,
-                    file,
+                     file,
-                    vec![attr.clone()]
+                     vec![attr.clone()]
-                ).is_ok()
+                 ) {
-            })
+                     Ok(_) => Ok(attr.clone()),
+                     Err(f) => Err((attr.clone(), lines_from_file(f)))
+                 }
+            )
+            .collect();
+
+        partition_result(attr_instantiations)
     }
 
     pub fn safely_instantiate_attrs(
@@ -253,6 +263,15 @@ impl Nix {
     }
 }
 
+fn lines_from_file(file: File) -> Vec<String> {
+    BufReader::new(file)
+        .lines()
+        .into_iter()
+        .filter(|line| line.is_ok())
+        .map(|line| line.unwrap())
+        .collect()
+}
+
 #[cfg(test)]
 mod tests {
     fn nix() -> Nix {
@@ -291,15 +310,6 @@ mod tests {
         Fail,
     }
 
-    fn lines_from_file(file: File) -> Vec<String> {
-        BufReader::new(file)
-            .lines()
-            .into_iter()
-            .filter(|line| line.is_ok())
-            .map(|line| line.unwrap())
-            .collect()
-    }
-
     fn assert_run(res: Result<File, File>, expected: Expect, require: Vec<&str>) {
         let expectation_held: bool = match expected {
             Expect::Pass => res.is_ok(),
@@ -378,8 +388,6 @@ mod tests {
     }
 
     use super::*;
-    use std::io::BufReader;
-    use std::io::BufRead;
     use std::path::PathBuf;
     use std::env;
 
@@ -567,7 +575,7 @@ mod tests {
     fn partition_instantiable_attributes() {
         let nix = nix();
 
-        let ret: (Vec<String>, Vec<String>) = nix.safely_partition_instantiable_attrs(
+        let ret: (Vec<String>, Vec<(String, Vec<String>)>) = nix.safely_partition_instantiable_attrs(
             individual_eval_path().as_path(),
             "default.nix",
             vec![
@@ -578,7 +586,12 @@ mod tests {
         );
 
         assert_eq!(ret.0, vec!["passes-instantiation"]);
-        assert_eq!(ret.1, vec!["fails-instantiation", "missing-attr"]);
+
+        assert_eq!(ret.1[0].0, "fails-instantiation");
+        assert_eq!(ret.1[0].1[0], "trace: You just can\'t frooble the frozz on this particular system.");
+
+        assert_eq!(ret.1[1].0, "missing-attr");
+        assert_eq!(ret.1[1].1[0], "error: attribute ‘missing-attr’ in selection path ‘missing-attr’ not found");
     }
 
     #[test]

ofborg/src/tasks/build.rs

@@ -23,7 +23,6 @@ pub struct BuildWorker {
     nix: nix::Nix,
     system: String,
     identity: String,
-    full_logs: bool,
 }
 
 impl BuildWorker {
@@ -32,14 +31,12 @@ impl BuildWorker {
         nix: nix::Nix,
         system: String,
         identity: String,
-        full_logs: bool,
     ) -> BuildWorker {
         return BuildWorker {
             cloner: cloner,
             nix: nix,
             system: system,
             identity: identity,
-            full_logs: full_logs,
         };
     }
 
@@ -58,6 +55,7 @@ pub struct JobActions<'a, 'b> {
     receiver: &'a mut notifyworker::NotificationReceiver,
     job: &'b buildjob::BuildJob,
     line_counter: u64,
+    snippet_log: VecDeque<String>,
     attempt_id: String,
     log_exchange: Option<String>,
     log_routing_key: Option<String>,
@@ -89,6 +87,7 @@ impl<'a, 'b> JobActions<'a, 'b> {
             receiver: receiver,
             job: job,
             line_counter: 0,
+            snippet_log: VecDeque::with_capacity(10),
             attempt_id: format!("{}", Uuid::new_v4()),
             log_exchange: log_exchange,
             log_routing_key: log_routing_key,
@@ -97,6 +96,13 @@ impl<'a, 'b> JobActions<'a, 'b> {
         };
     }
 
+    pub fn log_snippet(&self) -> Vec<String> {
+        self.snippet_log
+            .clone()
+            .into_iter()
+            .collect::<Vec<String>>()
+    }
+
     pub fn commit_missing(&mut self) {
         self.tell(worker::Action::Ack);
     }
@@ -152,9 +158,25 @@ impl<'a, 'b> JobActions<'a, 'b> {
         ));
     }
 
+    pub fn log_instantiation_errors(&mut self, cannot_build: Vec<(String, Vec<String>)>) {
+        for (attr, log) in cannot_build {
+            self.log_line(&format!("Cannot nix-instantiate `{}' because:", &attr));
+
+            for line in log {
+                self.log_line(&line);
+            }
+            self.log_line("");
+        }
+    }
+
     pub fn log_line(&mut self, line: &str) {
         self.line_counter += 1;
 
+        if self.snippet_log.len() >= 10 {
+            self.snippet_log.pop_front();
+        }
+        self.snippet_log.push_back(line.to_owned());
+
         let msg = buildlogmsg::BuildLogMsg {
             identity: self.identity.clone(),
             system: self.system.clone(),
@@ -180,7 +202,7 @@ impl<'a, 'b> JobActions<'a, 'b> {
             repo: self.job.repo.clone(),
             pr: self.job.pr.clone(),
             system: self.system.clone(),
-            output: vec![],
+            output: self.log_snippet(),
             attempt_id: self.attempt_id.clone(),
             skipped_attrs: Some(not_attempted_attrs),
             attempted_attrs: None,
@@ -206,7 +228,7 @@ impl<'a, 'b> JobActions<'a, 'b> {
         self.tell(worker::Action::Ack);
     }
 
-    pub fn build_finished(&mut self, success: bool, lines: Vec<String>,
+    pub fn build_finished(&mut self, success: bool,
                           attempted_attrs: Vec<String>,
                           not_attempted_attrs: Vec<String>,
 
@@ -215,7 +237,7 @@ impl<'a, 'b> JobActions<'a, 'b> {
             repo: self.job.repo.clone(),
             pr: self.job.pr.clone(),
             system: self.system.clone(),
-            output: lines,
+            output: self.log_snippet(),
             attempt_id: self.attempt_id.clone(),
             success: Some(success),
             attempted_attrs: Some(attempted_attrs),
@@ -323,12 +345,22 @@ impl notifyworker::SimpleNotifyWorker for BuildWorker {
             job.attrs.clone(),
         );
 
+        let cannot_build_attrs: Vec<String> = cannot_build
+            .clone()
+            .into_iter()
+            .map(|(attr,_)| attr)
+            .collect();
+
         println!("Can build: '{}', Cannot build: '{}'",
                  can_build.join(", "),
-                 cannot_build.join(", "));
+                 cannot_build_attrs.join(", "));
+
+
+        actions.log_started(can_build.clone(), cannot_build_attrs.clone());
+        actions.log_instantiation_errors(cannot_build);
 
         if can_build.len() == 0 {
-            actions.build_not_attempted(cannot_build);
+            actions.build_not_attempted(cannot_build_attrs);
             return;
         }
 
@@ -339,27 +371,11 @@ impl notifyworker::SimpleNotifyWorker for BuildWorker {
         );
 
         println!("About to execute {:?}", cmd);
-        actions.log_started(can_build.clone(), cannot_build.clone());
         let acmd = AsyncCmd::new(cmd);
         let mut spawned = acmd.spawn();
 
-        let mut snippet_log = VecDeque::with_capacity(10);
-
-
-        if !self.full_logs {
-            actions.log_line("Full logs are disabled on this builder.");
-        }
-
         for line in spawned.lines().iter() {
-            if self.full_logs {
+            actions.log_line(&line);
-                actions.log_line(&line);
-            }
-
-            if snippet_log.len() >= 10 {
-                snippet_log.pop_front();
-            }
-
-            snippet_log.push_back(line.to_owned());
         }
 
         let success = match spawned.wait() {
@@ -372,12 +388,11 @@ impl notifyworker::SimpleNotifyWorker for BuildWorker {
 
         println!("ok built ({:?}), building", success);
         println!("Lines:\n-----8<-----");
-        snippet_log.iter().inspect(|x| println!("{}", x)).last();
+        actions.log_snippet().iter().inspect(|x| println!("{}", x)).last();
         println!("----->8-----");
 
-        let last10lines: Vec<String> = snippet_log.into_iter().collect::<Vec<String>>();
 
-        actions.build_finished(success, last10lines.clone(), can_build, cannot_build);
+        actions.build_finished(success, can_build, cannot_build_attrs);
         println!("Done!");
     }
 }
@@ -409,7 +424,6 @@ mod tests {
             nix,
             "x86_64-linux".to_owned(),
             "cargo-test-build".to_owned(),
-            true,
         );
 
         return worker;
@@ -537,6 +551,8 @@ mod tests {
 
         println!("Total actions: {:?}", dummyreceiver.actions.len());
         let mut actions = dummyreceiver.actions.into_iter();
+        assert_contains_job(&mut actions, "\"line_number\":1,\"output\":\"Cannot nix-instantiate `not-real\' because:\"");
+        assert_contains_job(&mut actions, "\"line_number\":2,\"output\":\"error: attribute ‘not-real’ in selection path ‘not-real’ not found\"}");
         assert_contains_job(&mut actions, "skipped_attrs\":[\"not-real"); // First one to the github poster
         assert_contains_job(&mut actions, "skipped_attrs\":[\"not-real"); // This one to the logs
         assert_eq!(actions.next(), Some(worker::Action::Ack));

ofborg/src/tasks/githubcommentposter.rs

@@ -74,15 +74,16 @@ impl worker::SimpleWorker for GitHubCommentPoster {
 fn result_to_comment(result: &BuildResult) -> String {
     let mut reply: Vec<String> = vec![];
 
-    let log_link = match result.success {
+    let log_link = if result.output.len() > 0 {
-        Some(_) => format!(
+        format!(
             " [(full log)](https://logs.nix.ci/?key={}/{}.{}&attempt_id={})",
             &result.repo.owner.to_lowercase(),
             &result.repo.name.to_lowercase(),
             result.pr.number,
             result.attempt_id,
-        ),
+        )
-        None => "".to_owned()
+    } else {
+        "".to_owned()
     };
 
     reply.push(format!(
@@ -390,6 +391,45 @@ patching script interpreter paths in /nix/store/pcja75y9isdvgz5i00pkrpif9rxzxc29
 
     #[test]
     pub fn test_no_attempt() {
+        let result = BuildResult {
+            repo: Repo {
+                clone_url: "https://github.com/nixos/nixpkgs.git".to_owned(),
+                full_name: "NixOS/nixpkgs".to_owned(),
+                owner: "NixOS".to_owned(),
+                name: "nixpkgs".to_owned(),
+            },
+            pr: Pr {
+                head_sha: "abc123".to_owned(),
+                number: 2345,
+                target_branch: Some("master".to_owned()),
+            },
+            output: vec!["foo".to_owned()],
+            attempt_id: "foo".to_owned(),
+            system: "x86_64-linux".to_owned(),
+            attempted_attrs: None,
+            skipped_attrs: Some(vec!["not-attempted".to_owned()]),
+            success: None,
+        };
+
+        assert_eq!(
+            &result_to_comment(&result),
+            "No attempt on x86_64-linux [(full log)](https://logs.nix.ci/?key=nixos/nixpkgs.2345&attempt_id=foo)
+
+The following builds were skipped because they don't evaluate on x86_64-linux: not-attempted
+
+<details><summary>Partial log (click to expand)</summary><p>
+
+```
+foo
+```
+</p></details>
+
+"
+        );
+    }
+
+    #[test]
+    pub fn test_no_attempt_no_log() {
         let result = BuildResult {
             repo: Repo {
                 clone_url: "https://github.com/nixos/nixpkgs.git".to_owned(),