Implement forwarding of logs from core device to master.

Fixes #691.

artiq/coredevice/comm_mgmt.py

@@ -10,6 +10,7 @@ logger = logging.getLogger(__name__)
 class Request(Enum):
     GetLog = 1
     ClearLog = 2
+    PullLog = 7
     SetLogFilter = 3
     SetUartLogFilter = 6
 
@@ -121,6 +122,11 @@ class CommMgmt:
         self._write_header(Request.ClearLog)
         self._read_expect(Reply.Success)
 
+    def pull_log(self):
+        self._write_header(Request.PullLog)
+        self._read_expect(Reply.LogContent)
+        return self._read_string()
+
     def set_log_level(self, level):
         if level not in LogLevel.__members__:
             raise ValueError("invalid log level {}".format(level))

artiq/firmware/liblogger_artiq/lib.rs

@@ -47,7 +47,7 @@ impl BufferLogger {
         }
     }
 
-    pub fn with_instance<R, F: FnOnce(&BufferLogger) -> R>(f: F) -> R {
+    pub fn with<R, F: FnOnce(&BufferLogger) -> R>(f: F) -> R {
         f(unsafe { mem::transmute::<*const BufferLogger, &BufferLogger>(LOGGER) })
     }
 
@@ -55,8 +55,16 @@ impl BufferLogger {
         self.buffer.borrow_mut().clear()
     }
 
+    pub fn is_empty(&self) -> bool {
+        self.buffer.borrow_mut().extract().len() == 0
+    }
+
     pub fn extract<R, F: FnOnce(&str) -> R>(&self, f: F) -> R {
-        f(self.buffer.borrow_mut().extract())
+        let old_log_level = self.max_log_level();
+        self.set_max_log_level(LogLevelFilter::Off);
+        let result = f(self.buffer.borrow_mut().extract());
+        self.set_max_log_level(old_log_level);
+        result
     }
 
     pub fn max_log_level(&self) -> LogLevelFilter {
@@ -98,24 +106,14 @@ impl Log for BufferLogger {
             let seconds   = timestamp / 1_000_000;
             let micros    = timestamp % 1_000_000;
 
-            let force_uart = match self.buffer.try_borrow_mut() {
+            writeln!(self.buffer.borrow_mut(),
-                Ok(mut buffer) => {
+                     "[{:6}.{:06}s] {:>5}({}): {}", seconds, micros,
-                    writeln!(buffer, "[{:6}.{:06}s] {:>5}({}): {}",
+                     record.level(), record.target(), record.args()).unwrap();
-                             seconds, micros, record.level(),
-                             record.target(), record.args()).unwrap();
-                    false
-                }
-                Err(_) => {
-                    // we're trying to log something while sending the log somewhere,
-                    // probably over the network. just let it go to UART.
-                    true
-                }
-            };
 
-            if record.level() <= self.uart_filter.get() || force_uart {
+            if record.level() <= self.uart_filter.get() {
-                writeln!(Console, "[{:6}.{:06}s] {:>5}({}): {}",
+                writeln!(Console,
-                         seconds, micros, record.level(),
+                         "[{:6}.{:06}s] {:>5}({}): {}", seconds, micros,
-                         record.target(), record.args()).unwrap();
+                         record.level(), record.target(), record.args()).unwrap();
             }
         }
     }

artiq/firmware/libproto/mgmt_proto.rs

@@ -8,6 +8,7 @@ use log::LogLevelFilter;
 pub enum Request {
     GetLog,
     ClearLog,
+    PullLog,
     #[cfg(feature = "log")]
     SetLogFilter(LogLevelFilter),
     #[cfg(feature = "log")]
@@ -44,6 +45,7 @@ impl Request {
         Ok(match reader.read_u8()? {
             1  => Request::GetLog,
             2  => Request::ClearLog,
+            7  => Request::PullLog,
             #[cfg(feature = "log")]
             3 => Request::SetLogFilter(read_log_level_filter(reader)?),
             #[cfg(feature = "log")]

artiq/firmware/runtime/lib.rs

@@ -131,7 +131,7 @@ fn startup() {
         Ok(log_level_filter) => {
             info!("log level set to {} by `log_level` config key",
                   log_level_filter);
-            logger_artiq::BufferLogger::with_instance(|logger|
+            logger_artiq::BufferLogger::with(|logger|
                 logger.set_max_log_level(log_level_filter));
         }
     }
@@ -143,7 +143,7 @@ fn startup() {
         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_artiq::BufferLogger::with(|logger|
                 logger.set_uart_log_level(uart_log_level_filter));
         }
     }

artiq/firmware/runtime/mgmt.rs

@@ -1,9 +1,9 @@
 use std::io::{self, Read};
 use logger_artiq::BufferLogger;
-use log::LogLevelFilter;
 use sched::Io;
 use sched::{TcpListener, TcpStream};
 use board;
+use proto::WriteExt;
 use mgmt_proto::*;
 
 fn check_magic(stream: &mut TcpStream) -> io::Result<()> {
@@ -18,40 +18,49 @@ fn check_magic(stream: &mut TcpStream) -> io::Result<()> {
     }
 }
 
-fn worker(mut stream: &mut TcpStream) -> io::Result<()> {
+fn worker(io: &Io, stream: &mut TcpStream) -> io::Result<()> {
-    check_magic(&mut stream)?;
+    check_magic(stream)?;
     info!("new connection from {}", stream.remote_endpoint());
 
     loop {
         match Request::read_from(stream)? {
             Request::GetLog => {
-                BufferLogger::with_instance(|logger| {
+                BufferLogger::with(|logger| {
-                    let old_log_level = logger.max_log_level();
+                    logger.extract(|log| {
-                    logger.set_max_log_level(LogLevelFilter::Off);
-                    let result = logger.extract(|log| {
                         Reply::LogContent(log).write_to(stream)
-                    });
+                    })
-                    logger.set_max_log_level(old_log_level);
-                    result
                 })?;
             },
 
             Request::ClearLog => {
-                BufferLogger::with_instance(|logger|
+                BufferLogger::with(|logger|
                     logger.clear());
                 Reply::Success.write_to(stream)?;
             },
 
+            Request::PullLog => {
+                loop {
+                    io.until(|| BufferLogger::with(|logger| !logger.is_empty()))?;
+
+                    BufferLogger::with(|logger| {
+                        match logger.extract(|log| stream.write_string(log)) {
+                            Ok(()) => Ok(logger.clear()),
+                            Err(e) => Err(e)
+                        }
+                    })?;
+                }
+            },
+
             Request::SetLogFilter(level) => {
                 info!("changing log level to {}", level);
-                BufferLogger::with_instance(|logger|
+                BufferLogger::with(|logger|
                     logger.set_max_log_level(level));
                 Reply::Success.write_to(stream)?;
             },
 
             Request::SetUartLogFilter(level) => {
                 info!("changing UART log level to {}", level);
-                BufferLogger::with_instance(|logger|
+                BufferLogger::with(|logger|
                     logger.set_uart_log_level(level));
                 Reply::Success.write_to(stream)?;
             },
@@ -82,9 +91,10 @@ pub fn thread(io: Io) {
         let stream = listener.accept().expect("mgmt: cannot accept").into_handle();
         io.spawn(4096, move |io| {
             let mut stream = TcpStream::from_handle(&io, stream);
-            match worker(&mut stream) {
+            match worker(&io, &mut stream) {
                 Ok(()) => (),
                 Err(ref err) if err.kind() == io::ErrorKind::UnexpectedEof => (),
+                Err(ref err) if err.kind() == io::ErrorKind::WriteZero => (),
                 Err(err) => error!("aborted: {}", err)
             }
         });

artiq/frontend/aqctl_corelog.py

@@ -2,9 +2,14 @@
 
 import argparse
 import asyncio
+import struct
+import logging
+import re
 
-from artiq.protocols.pc_rpc import Server
 from artiq.tools import *
+from artiq.protocols.pc_rpc import Server
+from artiq.protocols.logging import log_with_name
+from artiq.coredevice.comm_mgmt import Request, Reply
 
 
 def get_argparser():
@@ -13,7 +18,6 @@ def get_argparser():
     simple_network_args(parser, 1068)
     parser.add_argument("core_addr",
                         help="hostname or IP address of the core device")
-    verbosity_args(parser)
     return parser
 
 
@@ -23,14 +27,35 @@ class PingTarget:
 
 
 async def get_logs(host):
+    reader, writer = await asyncio.open_connection(host, 1380)
+    writer.write(b"ARTIQ management\n")
+    writer.write(struct.pack("B", Request.PullLog.value))
+    await writer.drain()
+
     while True:
-        print("TODO: not implemented. host:", host)
+        length, = struct.unpack(">l", await reader.readexactly(4))
-        await asyncio.sleep(2)
+        log = await reader.readexactly(length)
+
+        for line in log.decode("utf-8").splitlines():
+            m = re.match(r"^\[.+?\] (TRACE|DEBUG| INFO| WARN|ERROR)\((.+?)\): (.+)$", line)
+            if m.group(1) == 'TRACE':
+                continue
+            elif m.group(1) == 'DEBUG':
+                level = logging.DEBUG
+            elif m.group(1) == ' INFO':
+                level = logging.INFO
+            elif m.group(1) == ' WARN':
+                level = logging.WARN
+            elif m.group(1) == 'ERROR':
+                level = logging.ERROR
+            name = 'firmware.' + m.group(2).replace('::', '.')
+            text = m.group(3)
+            log_with_name(name, level, text)
 
 
 def main():
     args = get_argparser().parse_args()
-    init_logger(args)
+    multiline_log_config(logging.DEBUG)
 
     loop = asyncio.get_event_loop()
     try:

artiq/tools.py

@@ -18,7 +18,7 @@ from artiq import __version__ as artiq_version
 
 __all__ = ["parse_arguments", "elide", "short_format", "file_import",
            "get_experiment", "verbosity_args", "simple_network_args",
-           "init_logger", "bind_address_from_args",
+           "multiline_log_config", "init_logger", "bind_address_from_args",
            "atexit_register_coroutine", "exc_to_warning",
            "asyncio_wait_or_cancel", "TaskObject", "Condition",
            "get_windows_drives", "get_user_config_dir"]