From c6e8d5c901575162d87036d14809a9866cae272f Mon Sep 17 00:00:00 2001 From: whitequark Date: Sat, 15 Apr 2017 08:27:18 +0000 Subject: [PATCH] runtime: allow setting UART log level explicitly. This is way more convenient than commenting out parts of session.rs when debugging. --- artiq/coredevice/comm_mgmt.py | 9 ++++++++ artiq/firmware/liblogger_artiq/lib.rs | 23 +++++++------------ artiq/firmware/libproto/mgmt_proto.rs | 32 ++++++++++++++++----------- artiq/firmware/runtime/lib.rs | 31 ++++++++++++++++++-------- artiq/firmware/runtime/mgmt.rs | 7 ++++++ artiq/firmware/runtime/session.rs | 3 --- artiq/frontend/artiq_corelog.py | 8 +++++++ 7 files changed, 73 insertions(+), 40 deletions(-) diff --git a/artiq/coredevice/comm_mgmt.py b/artiq/coredevice/comm_mgmt.py index 9f638e780..d4a787622 100644 --- a/artiq/coredevice/comm_mgmt.py +++ b/artiq/coredevice/comm_mgmt.py @@ -11,6 +11,7 @@ class Request(Enum): GetLog = 1 ClearLog = 2 SetLogFilter = 3 + SetUartLogFilter = 6 Hotswap = 4 Reboot = 5 @@ -128,6 +129,14 @@ class CommMgmt: self._write_int8(getattr(LogLevel, level).value) self._read_expect(Reply.Success) + def set_uart_log_level(self, level): + if level not in LogLevel.__members__: + raise ValueError("invalid log level {}".format(level)) + + self._write_header(Request.SetUartLogFilter) + self._write_int8(getattr(LogLevel, level).value) + self._read_expect(Reply.Success) + def hotswap(self, firmware): self._write_header(Request.Hotswap) self._write_bytes(firmware) diff --git a/artiq/firmware/liblogger_artiq/lib.rs b/artiq/firmware/liblogger_artiq/lib.rs index dda2e482d..c9cf3150a 100644 --- a/artiq/firmware/liblogger_artiq/lib.rs +++ b/artiq/firmware/liblogger_artiq/lib.rs @@ -1,6 +1,5 @@ #![no_std] -#[macro_use] extern crate log; extern crate log_buffer; extern crate board; @@ -8,14 +7,14 @@ extern crate board; use core::{mem, ptr}; use core::cell::{Cell, RefCell}; use core::fmt::Write; -use log::{Log, LogLevel, LogMetadata, LogRecord, LogLevelFilter, MaxLogLevelFilter}; +use log::{Log, LogMetadata, LogRecord, LogLevelFilter, MaxLogLevelFilter}; use log_buffer::LogBuffer; use board::{Console, clock}; pub struct BufferLogger { - buffer: RefCell>, - filter: RefCell>, - concise_uart: Cell + buffer: RefCell>, + filter: RefCell>, + uart_filter: Cell } static mut LOGGER: *const BufferLogger = 0 as *const _; @@ -25,7 +24,7 @@ impl BufferLogger { BufferLogger { buffer: RefCell::new(LogBuffer::new(buffer)), filter: RefCell::new(None), - concise_uart: Cell::new(true) + uart_filter: Cell::new(LogLevelFilter::Info), } } @@ -68,12 +67,8 @@ impl BufferLogger { .set(max_level) } - pub fn enable_concise_uart(&self) { - if self.concise_uart.get() { - trace!("disabling tracing to UART; all further trace messages \ - are sent to core log only"); - self.concise_uart.set(false) - } + pub fn set_uart_log_level(&self, max_level: LogLevelFilter) { + self.uart_filter.set(max_level) } } @@ -101,9 +96,7 @@ impl Log for BufferLogger { } }; - // Printing to UART is really slow, so avoid doing that when we have an alternative - // route to retrieve the debug messages. - if self.concise_uart.get() || record.level() <= LogLevel::Info || force_uart { + if record.level() <= self.uart_filter.get() || force_uart { writeln!(Console, "[{:12}us] {:>5}({}): {}", clock::get_us(), record.level(), record.target(), record.args()).unwrap(); diff --git a/artiq/firmware/libproto/mgmt_proto.rs b/artiq/firmware/libproto/mgmt_proto.rs index 7e299c02b..28b3f15f3 100644 --- a/artiq/firmware/libproto/mgmt_proto.rs +++ b/artiq/firmware/libproto/mgmt_proto.rs @@ -10,6 +10,8 @@ pub enum Request { ClearLog, #[cfg(feature = "log")] SetLogFilter(LogLevelFilter), + #[cfg(feature = "log")] + SetUartLogFilter(LogLevelFilter), Hotswap(Vec), Reboot, @@ -25,23 +27,27 @@ pub enum Reply<'a> { impl Request { pub fn read_from(reader: &mut Read) -> io::Result { + #[cfg(feature = "log")] + fn read_log_level_filter(reader: &mut Read) -> io::Result { + Ok(match reader.read_u8()? { + 0 => LogLevelFilter::Off, + 1 => LogLevelFilter::Error, + 2 => LogLevelFilter::Warn, + 3 => LogLevelFilter::Info, + 4 => LogLevelFilter::Debug, + 5 => LogLevelFilter::Trace, + _ => return Err(io::Error::new(io::ErrorKind::InvalidData, + "invalid log level")) + }) + } + Ok(match reader.read_u8()? { 1 => Request::GetLog, 2 => Request::ClearLog, #[cfg(feature = "log")] - 3 => { - let level = match reader.read_u8()? { - 0 => LogLevelFilter::Off, - 1 => LogLevelFilter::Error, - 2 => LogLevelFilter::Warn, - 3 => LogLevelFilter::Info, - 4 => LogLevelFilter::Debug, - 5 => LogLevelFilter::Trace, - _ => return Err(io::Error::new(io::ErrorKind::InvalidData, - "invalid log level")) - }; - Request::SetLogFilter(level) - } + 3 => Request::SetLogFilter(read_log_level_filter(reader)?), + #[cfg(feature = "log")] + 6 => Request::SetUartLogFilter(read_log_level_filter(reader)?), 4 => Request::Hotswap(reader.read_bytes()?), 5 => Request::Reboot, _ => return Err(io::Error::new(io::ErrorKind::InvalidData, "unknown request type")) diff --git a/artiq/firmware/runtime/lib.rs b/artiq/firmware/runtime/lib.rs index b84e5976a..61c35efbf 100644 --- a/artiq/firmware/runtime/lib.rs +++ b/artiq/firmware/runtime/lib.rs @@ -69,15 +69,6 @@ fn startup() { } info!("continuing boot"); - match config::read_str("log_level", |r| r?.parse()) { - Err(()) => (), - Ok(log_level_filter) => { - info!("log level set to {} in configuration", log_level_filter); - logger_artiq::BufferLogger::with_instance(|logger| - logger.set_max_log_level(log_level_filter)); - } - } - #[cfg(has_i2c)] board::i2c::init(); #[cfg(has_ad9516)] @@ -132,6 +123,28 @@ fn startup() { #[cfg(has_rtio_analyzer)] io.spawn(4096, analyzer::thread); + match config::read_str("log_level", |r| r?.parse()) { + Err(()) => (), + Ok(log_level_filter) => { + info!("log level set to {} by `log_level` config key", + log_level_filter); + logger_artiq::BufferLogger::with_instance(|logger| + logger.set_max_log_level(log_level_filter)); + } + } + + match config::read_str("uart_log_level", |r| r?.parse()) { + Err(()) => { + info!("UART log level set to INFO by default"); + }, + Ok(uart_log_level_filter) => { + info!("UART log level set to {} by `uart_log_level` config key", + uart_log_level_filter); + logger_artiq::BufferLogger::with_instance(|logger| + logger.set_uart_log_level(uart_log_level_filter)); + } + } + loop { scheduler.run(); diff --git a/artiq/firmware/runtime/mgmt.rs b/artiq/firmware/runtime/mgmt.rs index 8beae791d..13fb808af 100644 --- a/artiq/firmware/runtime/mgmt.rs +++ b/artiq/firmware/runtime/mgmt.rs @@ -44,6 +44,13 @@ fn worker(mut stream: &mut TcpStream) -> io::Result<()> { Reply::Success.write_to(stream)?; }, + Request::SetUartLogFilter(level) => { + info!("changing UART log level to {}", level); + BufferLogger::with_instance(|logger| + logger.set_uart_log_level(level)); + Reply::Success.write_to(stream)?; + }, + Request::Hotswap(firmware) => { Reply::RebootImminent.write_to(stream)?; stream.close()?; diff --git a/artiq/firmware/runtime/session.rs b/artiq/firmware/runtime/session.rs index b80b01d1b..1ec00a0c7 100644 --- a/artiq/firmware/runtime/session.rs +++ b/artiq/firmware/runtime/session.rs @@ -4,7 +4,6 @@ use std::cell::{Cell, RefCell}; use std::io::{self, Read, Write}; use std::error::Error; use {config, rtio_mgt, mailbox, rpc_queue, kernel}; -use logger_artiq::BufferLogger; use cache::Cache; use rtio_dma::Manager as DmaManager; use urc::Urc; @@ -668,8 +667,6 @@ pub fn thread(io: Io) { listener.listen(1381).expect("session: cannot listen"); info!("accepting network sessions"); - BufferLogger::with_instance(|logger| logger.enable_concise_uart()); - let congress = Urc::new(RefCell::new(Congress::new())); let mut kernel_thread = None; diff --git a/artiq/frontend/artiq_corelog.py b/artiq/frontend/artiq_corelog.py index d3720284f..76732c4bf 100755 --- a/artiq/frontend/artiq_corelog.py +++ b/artiq/frontend/artiq_corelog.py @@ -25,6 +25,12 @@ def get_argparser(): p_set_level.add_argument("level", metavar="LEVEL", type=str, help="log level (one of: OFF ERROR WARN INFO DEBUG TRACE)") + p_set_uart_level = subparsers.add_parser("set_uart_level", + help="set minimum level for messages to be logged " + "to UART") + p_set_uart_level.add_argument("level", metavar="LEVEL", type=str, + help="log level (one of: OFF ERROR WARN INFO DEBUG TRACE)") + return parser @@ -37,6 +43,8 @@ def main(): mgmt = CommMgmt(device_mgr, core_addr) if args.action == "set_level": mgmt.set_log_level(args.level) + elif args.action == "set_uart_level": + mgmt.set_uart_log_level(args.level) elif args.action == "clear": mgmt.clear_log() else: