blob: 1c3e40989f0bde3d9f6fc398fa267768384cd67e [file] [log] [blame] [edit]
// Copyright 2021 The ChromiumOS Authors
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
//! Implement consistent logging across the hibernate and resume transition.
use std::fs;
use std::fs::File;
use std::fs::OpenOptions;
use std::io::BufRead;
use std::io::BufReader;
use std::io::Cursor;
use std::io::Read;
use std::io::Write;
use std::mem;
use std::os::unix::fs::OpenOptionsExt;
use std::path::Path;
use std::path::PathBuf;
use std::str;
use std::sync::MutexGuard;
use std::time::Instant;
use anyhow::anyhow;
use anyhow::Context;
use anyhow::Result;
use log::debug;
use log::warn;
use log::Level;
use log::LevelFilter;
use log::Log;
use log::Metadata;
use log::Record;
use once_cell::sync::OnceCell;
use sync::Mutex;
use syslog::BasicLogger;
use syslog::Facility;
use syslog::Formatter3164;
use crate::files::HIBERMETA_DIR;
use crate::hiberutil::HibernateStage;
/// Define the path to kmsg, used to send log lines into the kernel buffer in
/// case a crash occurs.
const KMSG_PATH: &str = "/dev/kmsg";
/// Define the prefix to go on log messages.
const LOG_PREFIX: &str = "hiberman";
/// Define the name of the resume log file.
const RESUME_LOG_FILE_NAME: &str = "resume_log";
/// Define the name of the suspend log file.
const SUSPEND_LOG_FILE_NAME: &str = "suspend_log";
static STATE: OnceCell<Mutex<Hiberlog>> = OnceCell::new();
fn get_state() -> Result<&'static Mutex<Hiberlog>> {
STATE.get_or_try_init(|| Hiberlog::new().map(Mutex::new))
}
fn lock() -> Result<MutexGuard<'static, Hiberlog>> {
get_state().map(Mutex::lock)
}
/// Initialize the syslog connection and internal variables.
pub fn init() -> Result<()> {
// Warm up to initialize the state.
let _ = get_state()?;
log::set_boxed_logger(Box::new(HiberLogger::new()))
.map(|()| log::set_max_level(LevelFilter::Debug))?;
Ok(())
}
// Attempts to lock and retrieve the state. Returns from the function silently on failure.
macro_rules! lock {
() => {
match lock() {
Ok(s) => s,
_ => return,
}
};
}
/// Define the instance that gets handed to the logging crate.
struct HiberLogger {}
impl HiberLogger {
pub fn new() -> Self {
HiberLogger {}
}
}
impl Log for HiberLogger {
fn enabled(&self, _metadata: &Metadata) -> bool {
true
}
fn log(&self, record: &Record) {
let mut state = lock!();
state.log_record(record)
}
fn flush(&self) {
// nothing to do with O_SYNC files.
}
}
/// Define the possibilities as to where to route log lines to.
pub enum HiberlogOut {
/// Don't push log lines anywhere for now, just keep them in memory.
BufferInMemory,
/// Push log lines to the syslogger.
Syslog,
/// Push log lines to a File-like object.
File(Box<dyn Write + Send>),
}
/// Define the (singleton) hibernate logger state.
struct Hiberlog {
kmsg: File,
start: Instant,
pending: Vec<Vec<u8>>,
pending_size: usize,
to_kmsg: bool,
out: HiberlogOut,
pid: u32,
syslogger: BasicLogger,
is_empty: bool,
}
impl Hiberlog {
pub fn new() -> Result<Self> {
let kmsg = OpenOptions::new()
.read(true)
.write(true)
.open(KMSG_PATH)
.context("Failed to open kernel message logger")?;
let syslogger = create_syslogger();
Ok(Hiberlog {
kmsg,
start: Instant::now(),
pending: vec![],
pending_size: 0,
to_kmsg: false,
out: HiberlogOut::Syslog,
pid: std::process::id(),
syslogger,
is_empty: true,
})
}
/// Log a record.
fn log_record(&mut self, record: &Record) {
let mut buf = [0u8; 1024];
self.is_empty = false;
// If sending to the syslog, just forward there and exit.
if matches!(self.out, HiberlogOut::Syslog) {
self.syslogger.log(record);
return;
}
let res = {
let mut buf_cursor = Cursor::new(&mut buf[..]);
let facprio = priority_from_level(record.level()) + (Facility::LOG_USER as usize);
if let Some(file) = record.file() {
let duration = self.start.elapsed();
write!(
&mut buf_cursor,
"<{}>{}: {}.{:03} {} [{}:{}] ",
facprio,
LOG_PREFIX,
duration.as_secs(),
duration.subsec_millis(),
self.pid,
file,
record.line().unwrap_or(0)
)
} else {
write!(&mut buf_cursor, "<{}>{}: ", facprio, LOG_PREFIX)
}
.and_then(|()| writeln!(&mut buf_cursor, "{}", record.args()))
.map(|()| buf_cursor.position() as usize)
};
if let Ok(len) = &res {
if self.to_kmsg {
let _ = self.kmsg.write_all(&buf[..*len]);
}
if let HiberlogOut::File(f) = &mut self.out {
let _ = f.write_all(&buf[..*len]);
} else {
self.pending.push(buf[..*len].to_vec());
self.pending_size += *len;
}
}
}
/// Write any ending lines to the file.
fn flush_to_file(&mut self) {
if let HiberlogOut::File(f) = &mut self.out {
flush_to_backend(&self.pending, |s| {
f.write_all(s.as_bytes()).unwrap();
f.write_all(&[b'\n']).unwrap();
});
self.reset();
} else {
panic!("current log backend is not a file");
}
}
/// Push any pending lines to the syslog.
fn flush_to_syslog(&mut self) {
flush_to_backend(&self.pending, |s| {
replay_line(&self.syslogger, "M", s.to_string());
});
self.reset();
}
/// Empty the pending log buffer, discarding any unwritten messages. This is
/// used after a successful resume to avoid replaying what look like
/// unflushed logs from when the snapshot was taken. In reality these logs
/// got flushed after the snapshot was taken, just before the machine shut
/// down.
pub fn reset(&mut self) {
self.pending_size = 0;
self.pending = vec![];
self.is_empty = true;
}
}
fn flush_to_backend<F>(line_data: &Vec<Vec<u8>>, mut write_func: F)
where
F: FnMut(&str),
{
for line_vec in line_data {
let mut len = line_vec.len();
if len == 0 {
continue;
}
len -= 1;
let s = match str::from_utf8(&line_vec[0..len]) {
Ok(v) => v,
Err(_) => continue,
};
write_func(s);
}
}
/// Struct with associated functions for creating and opening hibernate
/// log files.
pub struct LogFile {}
impl LogFile {
/// Create the log file with the given path, truncate the file if it already
/// exists. The file is opened with O_SYNC to make sure data from writes
/// isn't buffered by the kernel but submitted to storage immediately.
pub fn create<P: AsRef<Path>>(path: P) -> Result<File> {
let opts = OpenOptions::new()
.create(true)
.truncate(true)
.write(true)
.custom_flags(libc::O_SYNC)
.clone();
Self::open_file(path, &opts)
}
/// Open an existing log file at the given path. The file is opened with
/// O_SYNC to make sure data from writes isn't buffered by the kernel but
/// submitted to storage immediately.
pub fn open<P: AsRef<Path>>(path: P) -> Result<File> {
Self::open_file(
path,
OpenOptions::new()
.read(true)
.write(true)
.custom_flags(libc::O_SYNC),
)
}
/// Get the path of the log file for a given hibernate stage.
pub fn get_path(stage: HibernateStage) -> PathBuf {
let name = match stage {
HibernateStage::Suspend => SUSPEND_LOG_FILE_NAME,
HibernateStage::Resume => RESUME_LOG_FILE_NAME,
};
Path::new(HIBERMETA_DIR).join(name)
}
fn open_file<P: AsRef<Path>>(path: P, open_options: &OpenOptions) -> Result<File> {
match open_options.open(&path) {
Ok(f) => Ok(f),
Err(e) => Err(anyhow!(e).context(format!(
"Failed to open log file '{}'",
path.as_ref().display()
))),
}
}
}
/// Divert the log to a new output. If the log was previously pointing to syslog
/// or a file, those messages are flushed. If the log was previously being
/// stored in memory, those messages will naturally flush to the given new
/// destination.
pub fn redirect_log(out: HiberlogOut) {
log::logger().flush();
let mut state = lock!();
state.to_kmsg = false;
let prev_out_was_memory = matches!(state.out, HiberlogOut::BufferInMemory);
state.out = out;
match state.out {
HiberlogOut::Syslog => state.flush_to_syslog(),
HiberlogOut::File(_) => {
// Any time we're redirecting to a file, also send to kmsg as a
// message in a bottle, in case we never get a chance to replay our
// own file logs. This shouldn't produce duplicate messages on
// success because when we're logging to a file we're also
// barrelling towards a kexec or shutdown.
state.to_kmsg = true;
if prev_out_was_memory {
state.flush_to_file();
}
}
_ => {}
}
}
/// Discard any buffered but unsent logging data.
pub fn reset_log() {
let mut state = lock!();
state.reset();
}
/// Replay the suspend (and maybe resume) logs to the syslogger.
pub fn replay_logs(push_resume_logs: bool, clear: bool) {
// Push the hibernate logs that were taken after the snapshot (and
// therefore after syslog became frozen) back into the syslog now.
// These should be there on both success and failure cases.
replay_log(HibernateStage::Suspend, clear);
// If successfully resumed from hibernate, or in the bootstrapping kernel
// after a failed resume attempt, also gather the resume logs
// saved by the bootstrapping kernel.
if push_resume_logs {
replay_log(HibernateStage::Resume, clear);
}
}
/// Helper function to replay the suspend or resume log to the syslogger, and
/// potentially zero out the log as well.
fn replay_log(stage: HibernateStage, clear: bool) {
let (name, prefix) = match stage {
HibernateStage::Suspend => ("suspend log", "S"),
HibernateStage::Resume => ("resume log", "R"),
};
let path = LogFile::get_path(stage);
if !path.exists() {
return;
}
let mut opened_log = match LogFile::open(&path) {
Ok(f) => f,
Err(e) => {
warn!("{}", e);
return;
}
};
replay_log_file(&mut opened_log, prefix, name);
if clear {
mem::drop(opened_log);
if let Err(e) = fs::remove_file(&path) {
warn!("Failed to remove {}: {}", path.display(), e);
}
}
}
/// Replay a generic log file to the syslogger.
fn replay_log_file(file: &mut dyn Read, prefix: &str, name: &str) {
let reader = BufReader::new(file);
let syslogger = create_syslogger();
syslogger.log(
&Record::builder()
.args(format_args!("Replaying {}:", name))
.level(Level::Info)
.build(),
);
for line in reader.lines() {
if let Ok(line) = line {
replay_line(&syslogger, prefix, line);
} else {
warn!("Invalid line in log file!");
}
}
syslogger.log(
&Record::builder()
.args(format_args!("Done replaying {}", name))
.level(Level::Info)
.build(),
);
}
/// Replay a single log line to the syslogger.
fn replay_line(syslogger: &BasicLogger, prefix: &str, line: String) {
// The log lines are in kmsg format, like:
// <11>hiberman: R [src/hiberman.rs:529] Hello 2004
// Trim off the first colon, everything after is line contents.
if line.is_empty() {
return;
}
let mut elements = line.splitn(2, ": ");
let header = elements.next().unwrap();
let contents = match elements.next() {
Some(c) => c,
None => {
warn!(
"Failed to split on colon: header: {}, line {:x?}, len {}",
header,
line.as_bytes(),
line.len()
);
return;
}
};
// Now trim <11>hiberman into <11, and parse 11 out of the combined
// priority + facility.
let facprio_string = header.split_once('>').map_or(header, |x| x.0);
let facprio: u8 = match facprio_string[1..].parse() {
Ok(i) => i,
Err(_) => {
warn!("Failed to parse facprio for next line, using debug");
debug!("{}", contents);
return;
}
};
let level = level_from_u8(facprio & 7);
syslogger.log(
&Record::builder()
.args(format_args!("{} {}", prefix, contents))
.level(level)
.build(),
);
}
fn level_from_u8(value: u8) -> Level {
match value {
0 => Level::Error,
1 => Level::Error,
2 => Level::Error,
3 => Level::Error,
4 => Level::Warn,
5 => Level::Info,
6 => Level::Info,
7 => Level::Debug,
_ => Level::Debug,
}
}
fn priority_from_level(level: Level) -> usize {
match level {
Level::Error => 3,
Level::Warn => 4,
Level::Info => 6,
Level::Debug => 7,
Level::Trace => 7,
}
}
fn create_syslogger() -> BasicLogger {
let formatter = Formatter3164 {
facility: Facility::LOG_USER,
hostname: None,
process: "hiberman".into(),
pid: std::process::id(),
};
let logger = syslog::unix(formatter).expect("Could not connect to syslog");
BasicLogger::new(logger)
}