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

@@ -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)

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<LogBuffer<&'static mut [u8]>>,
-    filter:       RefCell<Option<MaxLogLevelFilter>>,
-    concise_uart: Cell<bool>
+    buffer:      RefCell<LogBuffer<&'static mut [u8]>>,
+    filter:      RefCell<Option<MaxLogLevelFilter>>,
+    uart_filter: Cell<LogLevelFilter>
 }
 
 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();

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<u8>),
     Reboot,
@@ -25,23 +27,27 @@ pub enum Reply<'a> {
 
 impl Request {
     pub fn read_from(reader: &mut Read) -> io::Result<Request> {
+        #[cfg(feature = "log")]
+        fn read_log_level_filter(reader: &mut Read) -> io::Result<LogLevelFilter> {
+            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"))

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();
 

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()?;

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;

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: