From dd87508a7fc8726b4f834ab1df880687d5830f8b Mon Sep 17 00:00:00 2001 From: whitequark Date: Tue, 18 Jul 2017 04:10:33 +0000 Subject: [PATCH] Implement forwarding of logs from core device to master. Fixes #691. --- artiq/coredevice/comm_mgmt.py | 6 +++++ artiq/firmware/liblogger_artiq/lib.rs | 36 ++++++++++++------------- artiq/firmware/libproto/mgmt_proto.rs | 2 ++ artiq/firmware/runtime/lib.rs | 4 +-- artiq/firmware/runtime/mgmt.rs | 38 +++++++++++++++++---------- artiq/frontend/aqctl_corelog.py | 35 ++++++++++++++++++++---- artiq/tools.py | 2 +- 7 files changed, 82 insertions(+), 41 deletions(-) diff --git a/artiq/coredevice/comm_mgmt.py b/artiq/coredevice/comm_mgmt.py index e50a3167e..9a551a378 100644 --- a/artiq/coredevice/comm_mgmt.py +++ b/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)) diff --git a/artiq/firmware/liblogger_artiq/lib.rs b/artiq/firmware/liblogger_artiq/lib.rs index b4ca62993..87f6c53d1 100644 --- a/artiq/firmware/liblogger_artiq/lib.rs +++ b/artiq/firmware/liblogger_artiq/lib.rs @@ -47,7 +47,7 @@ impl BufferLogger { } } - pub fn with_instance R>(f: F) -> R { + pub fn with 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>(&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() { - Ok(mut buffer) => { - writeln!(buffer, "[{:6}.{:06}s] {:>5}({}): {}", - 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 - } - }; + writeln!(self.buffer.borrow_mut(), + "[{:6}.{:06}s] {:>5}({}): {}", seconds, micros, + record.level(), record.target(), record.args()).unwrap(); - if record.level() <= self.uart_filter.get() || force_uart { - writeln!(Console, "[{:6}.{:06}s] {:>5}({}): {}", - seconds, micros, record.level(), - record.target(), record.args()).unwrap(); + if record.level() <= self.uart_filter.get() { + writeln!(Console, + "[{:6}.{:06}s] {:>5}({}): {}", seconds, micros, + record.level(), record.target(), record.args()).unwrap(); } } } diff --git a/artiq/firmware/libproto/mgmt_proto.rs b/artiq/firmware/libproto/mgmt_proto.rs index 28b3f15f3..123af8915 100644 --- a/artiq/firmware/libproto/mgmt_proto.rs +++ b/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")] diff --git a/artiq/firmware/runtime/lib.rs b/artiq/firmware/runtime/lib.rs index c949220b8..67baaa08a 100644 --- a/artiq/firmware/runtime/lib.rs +++ b/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)); } } diff --git a/artiq/firmware/runtime/mgmt.rs b/artiq/firmware/runtime/mgmt.rs index 2d60fddfc..0e1819b5e 100644 --- a/artiq/firmware/runtime/mgmt.rs +++ b/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<()> { - check_magic(&mut stream)?; +fn worker(io: &Io, stream: &mut TcpStream) -> io::Result<()> { + check_magic(stream)?; info!("new connection from {}", stream.remote_endpoint()); loop { match Request::read_from(stream)? { Request::GetLog => { - BufferLogger::with_instance(|logger| { - let old_log_level = logger.max_log_level(); - logger.set_max_log_level(LogLevelFilter::Off); - let result = logger.extract(|log| { + BufferLogger::with(|logger| { + 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) } }); diff --git a/artiq/frontend/aqctl_corelog.py b/artiq/frontend/aqctl_corelog.py index fbff64691..f7a042df2 100755 --- a/artiq/frontend/aqctl_corelog.py +++ b/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) - await asyncio.sleep(2) + length, = struct.unpack(">l", await reader.readexactly(4)) + 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: diff --git a/artiq/tools.py b/artiq/tools.py index 5624ada2e..d7c3aab91 100644 --- a/artiq/tools.py +++ b/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"]