build logging into worker

artiq/frontend/artiq_client.py

@@ -1,6 +1,7 @@
 #!/usr/bin/env python3
 
 import argparse
+import logging
 import time
 import asyncio
 import sys
@@ -51,6 +52,10 @@ def get_argparser():
                                  "(defaults to head, ignored without -R)")
     parser_add.add_argument("-c", "--class-name", default=None,
                             help="name of the class to run")
+    parser_add.add_argument("-v", "--verbose", default=0, action="count",
+                            help="increase logging level of the experiment")
+    parser_add.add_argument("-q", "--quiet", default=0, action="count",
+                            help="decrease logging level of the experiment")
     parser_add.add_argument("file",
                             help="file containing the experiment to run")
     parser_add.add_argument("arguments", nargs="*",
@@ -110,6 +115,7 @@ def _action_submit(remote, args):
         sys.exit(1)
 
     expid = {
+        "log_level": logging.WARNING + args.quiet*10 - args.verbose*10,
         "file": args.file,
         "class_name": args.class_name,
         "arguments": arguments,

artiq/gui/explorer.py

@@ -1,4 +1,5 @@
 import asyncio
+import logging
 
 from quamash import QtGui, QtCore
 from pyqtgraph import dockarea
@@ -252,7 +253,14 @@ class ExplorerDock(dockarea.Dock):
 
         self.flush = QtGui.QCheckBox("Flush")
         self.flush.setToolTip("Flush the pipeline before starting the experiment")
-        grid.addWidget(self.flush, 2, 2, colspan=2)
+        grid.addWidget(self.flush, 2, 2)
+
+        self.log_level = QtGui.QComboBox()
+        for item in "DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL":
+            self.log_level.addItem(item)
+        self.log_level.setCurrentIndex(1)
+        self.log_level.setToolTip("Minimum level for log entry production")
+        grid.addWidget(self.log_level, 2, 3)
 
         submit = QtGui.QPushButton("Submit")
         grid.addWidget(submit, 3, 0, colspan=4)
@@ -317,6 +325,7 @@ class ExplorerDock(dockarea.Dock):
     async def submit(self, pipeline_name, file, class_name, arguments,
                priority, due_date, flush):
         expid = {
+            "log_level": getattr(logging, self.log_level.currentText()),
             "repo_rev": None,
             "file": file,
             "class_name": class_name,

artiq/language/__init__.py

@@ -1,11 +1,10 @@
 # Copyright (C) 2014, 2015 Robert Jordens <jordens@gmail.com>
 
-from artiq.language import core, environment, units, scan, logging
+from artiq.language import core, environment, units, scan
 from artiq.language.core import *
 from artiq.language.environment import *
 from artiq.language.units import *
 from artiq.language.scan import *
-from artiq.language.logging import *
 
 
 __all__ = []
@@ -13,4 +12,3 @@ __all__.extend(core.__all__)
 __all__.extend(environment.__all__)
 __all__.extend(units.__all__)
 __all__.extend(scan.__all__)
-__all__.extend(logging.__all__)

artiq/language/logging.py

@@ -1,23 +0,0 @@
-import logging
-
-from artiq.language.environment import *
-
-
-__all__ = ["LogExperiment"]
-
-
-class LogExperiment:
-    def init_logger(self):
-        """Call this from build() to add a logging level enumeration
-        widget, initialize logging globally, and create a logger.
-
-        Your class must also derive from ``HasEnvironment`` (or
-        ``EnvExperiment``).
-
-        The created logger is called ``self.logger``."""
-        level = self.get_argument("log_level", EnumerationValue(
-            ["DEBUG", "INFO", "WARNING", "ERROR", "CRITICAL"]))
-
-        if level is not None:
-            logging.basicConfig(level=getattr(logging, level))
-            self.logger = logging.getLogger(self.__class__.__name__)

artiq/master/worker.py

@@ -21,10 +21,6 @@ class WorkerWatchdogTimeout(Exception):
     pass
 
 
-class WorkerException(Exception):
-    pass
-
-
 class WorkerError(Exception):
     pass
 
@@ -60,13 +56,14 @@ class Worker:
         else:
             return None
 
-    async def _create_process(self):
+    async def _create_process(self, log_level):
         await self.io_lock.acquire()
         try:
             if self.closed.is_set():
                 raise WorkerError("Attempting to create process after close")
             self.process = await asyncio.create_subprocess_exec(
                 sys.executable, "-m", "artiq.master.worker_impl",
+                str(log_level),
                 stdout=subprocess.PIPE, stdin=subprocess.PIPE)
         finally:
             self.io_lock.release()
@@ -163,8 +160,6 @@ class Worker:
                 return True
             elif action == "pause":
                 return False
-            elif action == "exception":
-                raise WorkerException
             del obj["action"]
             if action == "create_watchdog":
                 func = self.create_watchdog
@@ -208,7 +203,7 @@ class Worker:
 
     async def build(self, rid, pipeline_name, wd, expid, priority, timeout=15.0):
         self.rid = rid
-        await self._create_process()
+        await self._create_process(expid["log_level"])
         await self._worker_action(
             {"action": "build",
              "rid": rid,
@@ -245,7 +240,7 @@ class Worker:
                                   timeout)
 
     async def examine(self, file, timeout=20.0):
-        await self._create_process()
+        await self._create_process(logging.WARNING)
         r = dict()
         def register(class_name, name, arguments):
             r[class_name] = {"name": name, "arguments": arguments}

artiq/master/worker_impl.py

@@ -1,7 +1,7 @@
 import sys
 import time
 import os
-import traceback
+import logging
 
 from artiq.protocols import pyon
 from artiq.tools import file_import
@@ -160,6 +160,7 @@ def examine(device_mgr, dataset_mgr, file):
 def main():
     sys.stdout = LogForwarder()
     sys.stderr = LogForwarder()
+    logging.basicConfig(level=int(sys.argv[1]))
 
     start_time = None
     rid = None
@@ -217,10 +218,10 @@ def main():
             elif action == "terminate":
                 break
     except:
-        traceback.print_exc()
+        logging.error("Worker terminating with exception", exc_info=True)
-        put_object({"action": "exception"})
     finally:
         device_mgr.close_devices()
 
+
 if __name__ == "__main__":
     main()

artiq/protocols/logging.py

@@ -61,7 +61,7 @@ class Server(AsyncioServer):
                     return
                 line = line[:-1]
                 linesplit = line.split(":", 3)
-                if len(linesplit) != 4:
+                if len(linesplit) != 2:
                     logger.warning("received improperly formatted message, "
                                    "dropping connection")
                     return

artiq/test/scheduler.py

@@ -1,4 +1,5 @@
 import unittest
+import logging
 import asyncio
 import sys
 import os
@@ -32,6 +33,7 @@ class BackgroundExperiment(EnvExperiment):
 
 def _get_expid(name):
     return {
+        "log_level": logging.WARNING,
         "file": sys.modules[__name__].__file__,
         "class_name": name,
         "arguments": dict()

artiq/test/worker.py

@@ -1,4 +1,5 @@
 import unittest
+import logging
 import asyncio
 import sys
 import os
@@ -64,6 +65,7 @@ async def _call_worker(worker, expid):
 
 def _run_experiment(class_name):
     expid = {
+        "log_level": logging.WARNING,
         "file": sys.modules[__name__].__file__,
         "class_name": class_name,
         "arguments": dict()
@@ -85,7 +87,7 @@ class WorkerCase(unittest.TestCase):
         _run_experiment("SimpleExperiment")
 
     def test_exception(self):
-        with self.assertRaises(WorkerException):
+        with self.assertRaises(WorkerError):
             _run_experiment("ExceptionTermination")
 
     def test_watchdog_no_timeout(self):

examples/master/dataset_db.pyon

@@ -1 +1 @@
-{"flopping_freq": 1499.9876804260716}
+{"flopping_freq": 1499.9977914479744}

examples/master/repository/arguments_demo.py

@@ -1,3 +1,5 @@
+import logging
+
 from artiq import *
 
 
@@ -33,10 +35,8 @@ class SubComponent2(HasEnvironment):
         print(self.sc2_enum)
 
 
-class ArgumentsDemo(EnvExperiment, LogExperiment):
+class ArgumentsDemo(EnvExperiment):
     def build(self):
-        self.init_logger()
-
         self.setattr_argument("free_value", FreeValue(None))
         self.setattr_argument("number", NumberValue(42e-6,
                                                     unit="us", scale=1e-6,
@@ -53,10 +53,10 @@ class ArgumentsDemo(EnvExperiment, LogExperiment):
         self.sc2 = SubComponent2(parent=self)
 
     def run(self):
-        self.logger.error("logging test: error")
+        logging.error("logging test: error")
-        self.logger.warning("logging test: warning")
+        logging.warning("logging test: warning")
-        self.logger.info("logging test: info")
+        logging.info("logging test: info")
-        self.logger.debug("logging test: debug")
+        logging.debug("logging test: debug")
 
         print(self.free_value)
         print(self.boolean)