m-labs · Jan 24, 2016 · Jan 24, 2016 · Jan 24, 2016
Showing with 57 additions and 35 deletions.

+9 −13 artiq/gui/log.py

+10 −5 artiq/master/experiments.py

+3 −3 artiq/master/log.py

+4 −4 artiq/master/scheduler.py

+21 −2 artiq/master/worker.py

+10 −8 artiq/master/worker_impl.py
diff --git a/artiq/gui/log.py b/artiq/gui/log.py
@@ -25,7 +25,7 @@ class Model(QtCore.QAbstractTableModel):
     def __init__(self, init):
         QtCore.QAbstractTableModel.__init__(self)
 
-        self.headers = ["Level", "Source", "Time", "Message"]
+        self.headers = ["Source", "Message"]
 
         self.entries = list(map(_make_wrappable, init))
         self.pending_entries = []
@@ -85,7 +85,7 @@ def timer_tick(self):
     def data(self, index, role):
         if index.isValid():
             if (role == QtCore.Qt.FontRole
-                    and index.column() == 3):
+                    and index.column() == 1):
                 return self.fixed_font
             elif role == QtCore.Qt.BackgroundRole:
                 level = self.entries[index.row()][0]
@@ -105,13 +105,13 @@ def data(self, index, role):
                 v = self.entries[index.row()]
                 column = index.column()
                 if column == 0:
-                    return log_level_to_name(v[0])
-                elif column == 1:
                     return v[1]
-                elif column == 2:
-                    return time.strftime("%m/%d %H:%M:%S", time.localtime(v[2]))
                 else:
                     return v[3]
+            elif role == QtCore.Qt.ToolTipRole:
+                v = self.entries[index.row()]
+                return (log_level_to_name(v[0]) + ", " +
+                    time.strftime("%m/%d %H:%M:%S", time.localtime(v[2])))
 
 
 class _LogFilterProxyModel(QSortFilterProxyModel):
@@ -123,15 +123,11 @@ def __init__(self, min_level, freetext):
     def filterAcceptsRow(self, sourceRow, sourceParent):
         model = self.sourceModel()
 
-        index = model.index(sourceRow, 0, sourceParent)
-        data = model.data(index, QtCore.Qt.DisplayRole)
-        accepted_level = getattr(logging, data) >= self.min_level
+        accepted_level = model.entries[sourceRow][0] >= self.min_level
 
         if self.freetext:
-            index = model.index(sourceRow, 1, sourceParent)
-            data_source = model.data(index, QtCore.Qt.DisplayRole)
-            index = model.index(sourceRow, 3, sourceParent)
-            data_message = model.data(index, QtCore.Qt.DisplayRole)
+            data_source = model.entries[sourceRow][1]
+            data_message = model.entries[sourceRow][3]
             accepted_freetext = (self.freetext in data_source
                 or self.freetext in data_message)
         else:

diff --git a/artiq/master/experiments.py b/artiq/master/experiments.py
@@ -6,7 +6,8 @@
 from functools import partial
 
 from artiq.protocols.sync_struct import Notifier
-from artiq.master.worker import Worker
+from artiq.master.worker import (Worker, WorkerInternalException,
+                                 log_worker_exception)
 from artiq.tools import get_windows_drives, exc_to_warning
 
 
@@ -17,10 +18,13 @@ async def _get_repository_entries(entry_dict,
                                   root, filename, get_device_db, log):
     worker = Worker({
         "get_device_db": get_device_db,
-        "log": partial(log, "scan")
+        "log": partial(log, "scan", os.path.basename(filename))
     })
     try:
         description = await worker.examine(os.path.join(root, filename))
+    except:
+        log_worker_exception()
+        raise
     finally:
         await worker.close()
     for class_name, class_desc in description.items():
@@ -55,8 +59,9 @@ async def _scan_experiments(root, get_device_db, log, subdir=""):
             try:
                 await _get_repository_entries(
                     entry_dict, root, filename, get_device_db, log)
-            except:
-                logger.warning("Skipping file '%s'", filename, exc_info=True)
+            except Exception as exc:
+                logger.warning("Skipping file '%s'", filename,
+                    exc_info=not isinstance(exc, WorkerInternalException))
         if de.is_dir():
             subentries = await _scan_experiments(
                 root, get_device_db, log,
@@ -119,7 +124,7 @@ async def examine(self, filename, use_repository=True):
             filename = os.path.join(wd, filename)
         worker = Worker({
             "get_device_db": self.get_device_db_fn,
-            "log": partial(self.log_fn, "examine")
+            "log": partial(self.log_fn, "examine", os.path.basename(filename))
         })
         try:
             description = await worker.examine(filename)

diff --git a/artiq/master/log.py b/artiq/master/log.py
@@ -29,11 +29,11 @@ def emit(self, record):
                                 part)
 
 
-def log_worker(rid, message):
+def log_worker(rid, filename, message):
     level, name, message = parse_log_message(message)
     log_with_name(name, level, message,
-                  extra={"source": "worker({})".format(rid)})
-log_worker.worker_pass_rid = True
+                  extra={"source": "worker({},{})".format(rid, filename)})
+log_worker.worker_pass_runinfo = True
 
 
 def log_args(parser):

diff --git a/artiq/master/scheduler.py b/artiq/master/scheduler.py
@@ -3,7 +3,7 @@
 from enum import Enum
 from time import time
 
-from artiq.master.worker import Worker
+from artiq.master.worker import Worker, log_worker_exception
 from artiq.tools import asyncio_wait_or_cancel, TaskObject, Condition
 from artiq.protocols.sync_struct import Notifier
 
@@ -231,7 +231,7 @@ async def _do(self):
                 except:
                     logger.error("got worker exception in prepare stage, "
                                  "deleting RID %d", run.rid)
-                    logger.error("worker exception details", exc_info=True)
+                    log_worker_exception()
                     self.delete_cb(run.rid)
                 else:
                     run.status = RunStatus.prepare_done
@@ -281,7 +281,7 @@ async def _do(self):
             except:
                 logger.error("got worker exception in run stage, "
                              "deleting RID %d", run.rid)
-                logger.error("worker exception details", exc_info=True)
+                log_worker_exception()
                 self.delete_cb(run.rid)
             else:
                 if completed:
@@ -319,7 +319,7 @@ async def _do(self):
             except:
                 logger.error("got worker exception in analyze stage, "
                              "deleting RID %d", run.rid)
-                logger.error("worker exception details", exc_info=True)
+                log_worker_exception()
                 self.delete_cb(run.rid)
             else:
                 self.delete_cb(run.rid)

diff --git a/artiq/master/worker.py b/artiq/master/worker.py
@@ -1,4 +1,5 @@
 import sys
+import os
 import asyncio
 import logging
 import subprocess
@@ -25,12 +26,27 @@ class WorkerError(Exception):
     pass
 
 
+class WorkerInternalException(Exception):
+    """Exception raised inside the worker, information has been printed
+    through logging."""
+    pass
+
+
+def log_worker_exception():
+    exc, _, _ = sys.exc_info()
+    if exc is WorkerInternalException:
+        logger.debug("worker exception details", exc_info=True)
+    else:
+        logger.error("worker exception details", exc_info=True)
+
+
 class Worker:
     def __init__(self, handlers=dict(), send_timeout=0.5):
         self.handlers = handlers
         self.send_timeout = send_timeout
 
         self.rid = None
+        self.filename = None
         self.process = None
         self.watchdogs = dict()  # wid -> expiration (using time.monotonic)
 
@@ -167,6 +183,8 @@ async def _handle_worker_requests(self):
                 return True
             elif action == "pause":
                 return False
+            elif action == "exception":
+                raise WorkerInternalException
             elif action == "create_watchdog":
                 func = self.create_watchdog
             elif action == "delete_watchdog":
@@ -175,8 +193,8 @@ async def _handle_worker_requests(self):
                 func = self.register_experiment
             else:
                 func = self.handlers[action]
-            if getattr(func, "worker_pass_rid", False):
-                func = partial(func, self.rid)
+            if getattr(func, "worker_pass_runinfo", False):
+                func = partial(func, self.rid, self.filename)
             try:
                 data = func(*obj["args"], **obj["kwargs"])
                 reply = {"status": "ok", "data": data}
@@ -211,6 +229,7 @@ async def _worker_action(self, obj, timeout=None):
 
     async def build(self, rid, pipeline_name, wd, expid, priority, timeout=15.0):
         self.rid = rid
+        self.filename = os.path.basename(expid["file"])
         await self._create_process(expid["log_level"])
         await self._worker_action(
             {"action": "build",

diff --git a/artiq/master/worker_impl.py b/artiq/master/worker_impl.py
@@ -264,15 +264,17 @@ def main():
                 put_object({"action": "completed"})
             elif action == "terminate":
                 break
-    except CompileError:
-        pass
     except Exception as exc:
-        lines = ["Terminating with exception\n"]
-        lines += traceback.format_exception_only(type(exc), exc)
-        if hasattr(exc, "parent_traceback"):
-            lines += exc.parent_traceback
-        logging.error("".join(lines).rstrip(),
-                      exc_info=not hasattr(exc, "parent_traceback"))
+        # When we get CompileError, a more suitable diagnostic has already
+        # been printed.
+        if not isinstance(exc, CompileError):
+            lines = ["Terminating with exception\n"]
+            lines += traceback.format_exception_only(type(exc), exc)
+            if hasattr(exc, "parent_traceback"):
+                lines += exc.parent_traceback
+            logging.error("".join(lines).rstrip(),
+                          exc_info=not hasattr(exc, "parent_traceback"))
+        put_object({"action": "exception"})
     finally:
         device_mgr.close_devices()