analyzer: explicitly delimit messages (with \x1D).

Fixes #461.

artiq/compiler/transforms/artiq_ir_generator.py

@@ -1672,7 +1672,7 @@ class ARTIQIRGenerator(algorithm.Visitor):
             self.polymorphic_print([self.visit(prefix)],
                                    separator=" ", suffix="\x1E", as_rtio=True)
             self.polymorphic_print([self.visit(arg) for arg in args],
-                                   separator=" ", suffix="\n", as_rtio=True)
+                                   separator=" ", suffix="\n\x1D", as_rtio=True)
             return ir.Constant(None, builtins.TNone())
         elif types.is_builtin(typ, "now"):
             if len(node.args) == 0 and len(node.keywords) == 0:

artiq/coredevice/analyzer.py

@@ -278,11 +278,9 @@ class LogHandler:
 
     def process_message(self, message):
         if isinstance(message, OutputMessage):
-            message_payload = _extract_log_chars(message.data)
+            self.current_entry += _extract_log_chars(message.data)
-            self.current_entry += message_payload
+            if len(self.current_entry) > 1 and self.current_entry[-1] == "\x1D":
-            if len(message_payload) < 4:
+                channel_name, log_message = self.current_entry[:-1].split("\x1E", maxsplit=1)
-                channel_name, log_message = \
-                    self.current_entry.split(":", maxsplit=1)
                 vcd_value = ""
                 for c in log_message:
                     vcd_value += "{:08b}".format(ord(c))
@@ -296,10 +294,9 @@ def get_vcd_log_channels(log_channel, messages):
     for message in messages:
         if (isinstance(message, OutputMessage)
                 and message.channel == log_channel):
-            message_payload = _extract_log_chars(message.data)
+            log_entry += _extract_log_chars(message.data)
-            log_entry += message_payload
+            if len(log_entry) > 1 and log_entry[-1] == "\x1D":
-            if len(message_payload) < 4:
+                channel_name, log_message = log_entry[:-1].split("\x1E", maxsplit=1)
-                channel_name, log_message = log_entry.split("\x1E", maxsplit=1)
                 l = len(log_message)
                 if channel_name in vcd_log_channels:
                     if vcd_log_channels[channel_name] < l:

artiq/test/coredevice/test_analyzer.py

@@ -1,6 +1,7 @@
 from artiq.experiment import *
 from artiq.coredevice.analyzer import (decode_dump, StoppedMessage,
-                                       OutputMessage, InputMessage)
+                                       OutputMessage, InputMessage,
+                                       _extract_log_chars)
 from artiq.test.hardware_testbench import ExperimentCase
 
 
@@ -26,6 +27,15 @@ class CreateTTLPulse(EnvExperiment):
         self.loop_in.count()
 
 
+class WriteLog(EnvExperiment):
+    def build(self):
+        self.setattr_device("core")
+
+    @kernel
+    def run(self):
+        rtio_log("foo", 32)
+
+
 class AnalyzerTest(ExperimentCase):
     def test_ttl_pulse(self):
         comm = self.device_mgr.get("comm")
@@ -50,3 +60,16 @@ class AnalyzerTest(ExperimentCase):
         self.assertAlmostEqual(
             abs(input_messages[0].timestamp - input_messages[1].timestamp),
             1000, delta=1)
+
+    def test_rtio_log(self):
+        comm = self.device_mgr.get("comm")
+
+        exp = self.create(WriteLog)
+        comm.get_analyzer_dump()  # clear analyzer buffer
+        exp.run()
+
+        dump = decode_dump(comm.get_analyzer_dump())
+        log  = "".join([_extract_log_chars(msg.data)
+                        for msg in dump.messages
+                        if isinstance(msg, OutputMessage) and msg.channel == dump.log_channel])
+        self.assertEqual(log, "foo\x1E32\n\x1D")