Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Use pipes instead of file for logging in tests #3074

Merged
merged 18 commits into from
Mar 8, 2021
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -301,11 +301,18 @@ impl ConfigurationBuilder {
(None, false) => default_log_file(),
(None, true) => {
let path = default_log_file();
node_config.log = Some(Log(vec![LogEntry {
level: "trace".to_string(),
format: "json".to_string(),
output: LogOutput::File(path.clone()),
}]));
node_config.log = Some(Log(vec![
LogEntry {
level: "trace".to_string(),
format: "json".to_string(),
output: LogOutput::Stdout,
},
LogEntry {
level: "trace".to_string(),
format: "json".to_string(),
output: LogOutput::File(path.clone()),
},
]));
path
}
};
Expand Down Expand Up @@ -382,7 +389,6 @@ impl ConfigurationBuilder {
);

params.write_node_config();

params
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -12,19 +12,16 @@ use jormungandr_testing_utils::testing::MemPoolCheck;
pub use process::*;
pub use starter::*;
use std::collections::HashMap;
use std::path::PathBuf;
use thiserror::Error;

use jormungandr_testing_utils::testing::{FragmentNode, FragmentNodeError};

#[derive(Error, Debug)]
pub enum JormungandrError {
#[error("error in logs. Error lines: {error_lines}, logs location: {log_location}, full content:{logs}")]
ErrorInLogs {
logs: String,
log_location: PathBuf,
error_lines: String,
},
#[error("error in logs. Error lines: {error_lines}, full content:{logs}")]
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Suggested change
#[error("error in logs. Error lines: {error_lines}, full content:{logs}")]
#[error("error in logs. Error lines: {error_lines}, full content: {logs}")]

Not really sure it's useful to put the full JSON content in a single error printout. Maybe the test fixture handling this error can re-parse the logs field and print the lines out nicely?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe we could reuse log formatting from tracing_subscriber::fmt but I'm not sure if it can be used independently, need to check.

ErrorInLogs { logs: String, error_lines: String },
#[error("error(s) in log detected: port already in use")]
PortAlreadyInUse,
}

impl FragmentNode for JormungandrProcess {
Expand Down Expand Up @@ -72,6 +69,6 @@ impl FragmentNode for JormungandrProcess {
println!("Fragment '{}' in block: {} ({})", fragment_id, block, date);
}
fn log_content(&self) -> Vec<String> {
self.logger.get_lines_from_log().collect()
self.logger.get_lines_as_string()
}
}
Original file line number Diff line number Diff line change
@@ -1,5 +1,5 @@
use super::JormungandrError;
use crate::common::jcli::JCli;
use crate::common::jcli::{JCli, JCliCommand};
use assert_fs::TempDir;
use chain_impl_mockchain::fee::LinearFee;
use chain_time::TimeEra;
Expand All @@ -10,16 +10,29 @@ use jormungandr_lib::{
use jormungandr_testing_utils::testing::{
node::{
uri_from_socket_addr, Explorer, JormungandrLogger, JormungandrRest,
JormungandrStateVerifier,
JormungandrStateVerifier, LogLevel,
},
JormungandrParams, SyncNode, TestConfig,
};
use jormungandr_testing_utils::testing::{RemoteJormungandr, RemoteJormungandrBuilder};
use jortestkit::prelude::ProcessOutput;
use std::net::SocketAddr;
use std::path::Path;
use std::process::Child;
use std::process::Stdio;
use std::str::FromStr;

pub enum StartupVerificationMode {
Log,
Rest,
}

pub enum Status {
Running,
Starting,
Stopped(JormungandrError),
}

pub struct JormungandrProcess {
pub child: Child,
pub logger: JormungandrLogger,
Expand All @@ -34,18 +47,18 @@ pub struct JormungandrProcess {

impl JormungandrProcess {
pub(crate) fn from_config<Conf: TestConfig>(
child: Child,
mut child: Child,
params: &JormungandrParams<Conf>,
temp_dir: Option<TempDir>,
alias: String,
) -> Self {
let log_file_path = params.log_file_path();
let node_config = params.node_config();
let stdout = child.stdout.take().unwrap();
JormungandrProcess {
child,
temp_dir,
alias,
logger: JormungandrLogger::new(log_file_path),
logger: JormungandrLogger::new(stdout),
p2p_public_address: node_config.p2p_public_address(),
rest_socket_addr: node_config.rest_socket_addr(),
genesis_block_hash: Hash::from_str(params.genesis_block_hash()).unwrap(),
Expand All @@ -54,6 +67,60 @@ impl JormungandrProcess {
}
}

pub fn status(&self, strategy: &StartupVerificationMode) -> Status {
let port_occupied_msgs = ["error 87", "error 98", "panicked at 'Box<Any>'"];
mzabaluev marked this conversation as resolved.
Show resolved Hide resolved
if self.logger.contains_any_of(&port_occupied_msgs) {
return Status::Stopped(JormungandrError::PortAlreadyInUse);
}
if let Err(err) = self.check_no_errors_in_log() {
return Status::Stopped(err);
}

match strategy {
StartupVerificationMode::Log => {
let bootstrap_completed_msgs = [
"listening and accepting gRPC connections",
"genesis block fetched",
];

if self.logger.contains_any_of(&bootstrap_completed_msgs) {
Status::Running
} else {
Status::Starting
}
}
StartupVerificationMode::Rest => {
let jcli: JCli = Default::default();

let output = JCliCommand::new(std::process::Command::new(jcli.path()))
.rest()
.v0()
.node()
.stats(&self.rest_uri())
.build()
.stdout(Stdio::piped())
.stderr(Stdio::piped())
.spawn()
.unwrap()
.wait_with_output()
.expect("failed to execute get_rest_stats command");

let output = output.try_as_single_node_yaml();

match output.ok().and_then(|x| x.get("uptime").cloned()) {
Some(uptime)
if uptime.parse::<i32>().unwrap_or_else(|_| {
panic!("Cannot parse uptime {}", uptime.to_string())
}) > 2 =>
{
Status::Running
}
_ => Status::Starting,
}
}
}
}

pub fn alias(&self) -> &str {
&self.alias
}
Expand Down Expand Up @@ -92,12 +159,14 @@ impl JormungandrProcess {
}

pub fn check_no_errors_in_log(&self) -> Result<(), JormungandrError> {
let error_lines = self.logger.get_lines_with_error().collect::<Vec<String>>();
let error_lines = self
.logger
.get_lines_with_level(LogLevel::ERROR)
.collect::<Vec<_>>();

if !error_lines.is_empty() {
return Err(JormungandrError::ErrorInLogs {
logs: self.logger.get_log_content(),
log_location: self.logger.log_file_path.clone(),
error_lines: format!("{:?}", error_lines),
});
}
Expand Down Expand Up @@ -150,9 +219,7 @@ impl JormungandrProcess {

pub fn to_remote(&self) -> RemoteJormungandr {
let mut builder = RemoteJormungandrBuilder::new(self.alias.clone());
builder
.with_rest(self.rest_socket_addr)
.with_logger(self.logger.log_file_path.clone());
builder.with_rest(self.rest_socket_addr);
builder.build()
}

Expand All @@ -172,12 +239,21 @@ impl JormungandrProcess {

impl Drop for JormungandrProcess {
fn drop(&mut self) {
let errors = self
.logger
.get_lines_with_level(LogLevel::ERROR)
.collect::<Vec<_>>();
if !errors.is_empty() {
println!("Error lines:");
for line in errors {
println!("{}", line);
}
}
// There's no kill like overkill
let _ = self.child.kill();

// FIXME: These should be better done in a test harness
self.child.wait().unwrap();
self.logger.print_error_and_invalid_logs();
}
}

Expand Down Expand Up @@ -209,10 +285,13 @@ impl SyncNode for JormungandrProcess {
}

fn get_lines_with_error_and_invalid(&self) -> Vec<String> {
self.logger.get_lines_with_error_and_invalid().collect()
self.logger
.get_lines_with_level(LogLevel::ERROR)
.map(|x| x.to_string())
.collect()
mzabaluev marked this conversation as resolved.
Show resolved Hide resolved
}

fn is_running(&self) -> bool {
todo!()
matches!(self.status(&StartupVerificationMode::Log), Status::Running)
}
mzabaluev marked this conversation as resolved.
Show resolved Hide resolved
}
Original file line number Diff line number Diff line change
Expand Up @@ -2,10 +2,9 @@ use super::{FromGenesis, Role};

use jormungandr_testing_utils::testing::{JormungandrParams, TestConfig};
use serde::Serialize;
use std::fs::File;
use std::iter::FromIterator;
use std::path::Path;
use std::process::{Command, Stdio};
use std::process::Command;

pub struct CommandBuilder<'a> {
bin: &'a Path,
Expand Down Expand Up @@ -94,29 +93,14 @@ impl<'a> CommandBuilder<'a> {
}
}

if let Some(log_file) = self.log_file {
command.stderr(get_stdio_from_log_file(log_file));
}
command.stderr(std::process::Stdio::piped());
command.stdout(std::process::Stdio::piped());

println!("Running start jormungandr command: {:?}", &command);
command
}
}

#[cfg(unix)]
fn get_stdio_from_log_file(log_file_path: &Path) -> std::process::Stdio {
use std::os::unix::io::{FromRawFd, IntoRawFd};
let file = File::create(log_file_path).expect("couldn't create log file for jormungandr");
unsafe { Stdio::from_raw_fd(file.into_raw_fd()) }
}

#[cfg(windows)]
fn get_stdio_from_log_file(log_file_path: &Path) -> std::process::Stdio {
use std::os::windows::io::{FromRawHandle, IntoRawHandle};
let file = File::create(log_file_path).expect("couldn't create log file for jormungandr");
unsafe { Stdio::from_raw_handle(file.into_raw_handle()) }
}

pub fn get_command<Conf: TestConfig + Serialize>(
params: &JormungandrParams<Conf>,
bin_path: impl AsRef<Path>,
Expand Down
Loading