RPC returning a list of tuple closes the core connection

Ffanmingyu212 · Oct 10, 2021

The following code crashes the experiment and raises a ConnectionResetError.

from artiq.experiment import *


class TestExperiment1(EnvExperiment):
    def build(self):
        self.setattr_device('core')

    def run(self):
        self.run_kernel()

    @rpc
    def get_data1(self) -> TList(TTuple([TInt32, TInt32, TStr, TFloat])):
        return [(1, 1, "a", 1.0), (2, 2, "b", -1.0)]

    @rpc
    def get_data2(self) -> TList(TTuple([TInt32, TStr, TFloat, TInt32])):
        return [(1, "a", 1.0, 1)]

    @rpc
    def get_data3(self) -> TList(TTuple([TInt32, TStr, TFloat, TInt32])):
        return [(1, "a", 1.0, 1), (2, "b", -1.0, 2)]

    @kernel
    def run_kernel(self):
        data1 = self.get_data1()
        for kk in range(len(data1)):
            print("data1: ", data1[kk])  # this works.

        data2 = self.get_data2()
        for kk in range(len(data2)):
            print("data2: ", data2[kk])  # this works.

        data3 = self.get_data3()
        for kk in range(len(data3)):
            print("data3: ", data3[kk])  # this does not work.

Everything works till the last line or the code, where it raises an ConnectionResetError instead of printing out each element in data3. Maybe it is related to https://forum.m-labs.hk/d/253-tuple-members-cannot-be-accessed-in-kernel-functions?

The error message is copied below with folder paths replaced by "...":

root:Terminating with exception (ConnectionResetError: Core device connection closed unexpectedly)
Traceback (most recent call last):
  File "...\worker_impl.py", line 300, in main
    exp_inst.run()
  File "...\test1.py", line 9, in run
    self.run_kernel()
  File "...\core.py", line 54, in run_on_core
    return getattr(self, arg).run(run_on_core, ((self,) + k_args), k_kwargs)
  File "...\core.py", line 137, in run
    self.comm.serve(embedding_map, symbolizer, demangler)
  File "...\comm_kernel.py", line 640, in serve
    self._read_header()
  File "...\comm_kernel.py", line 240, in _read_header
    sync_byte = self._read(1)[0]
  File "...\comm_kernel.py", line 228, in _read
    raise ConnectionResetError("Core device connection closed unexpectedly")
ConnectionResetError: Core device connection closed unexpectedly

The strange thing to me is that everything works if the order of the elements in a tuple changed (data1) or the length of the list set to 1 (data2).

The above test was done on Windows 10 python 3.8 with latest artiq master (8ccd00df) and a Kasli 2.0.

dpn · Oct 11, 2021

Maybe it is related to https://forum.m-labs.hk/d/253-tuple-members-cannot-be-accessed-in-kernel-functions?

This is unlikely to be related.

Seems likely to be a memory corruption issue of some sort, or a bug in the RPC code, perhaps introduced during the recent performance work.

Is there anything of note in the core device log (e.g. via UART)? You might also want to increase the log level to TRACE temporarily so you can see the internal RPC messages between the two core device CPUs.

Ffanmingyu212 · Oct 11, 2021

dpn thank you for the reply!

The core device log at TRACE log level relevant for the experiment is attached below:

[590411.942210s] INFO(runtime::session): new connection from 192.168.1.174:60046
[590411.950885s] DEBUG(runtime::session): comm<-host SystemInfo
[590411.955225s] DEBUG(runtime::session): comm->host SystemInfo { ident: "7.7817.4bfd010f.beta;ucsb", finished_cleanly: false }
[590411.971142s] DEBUG(runtime::session): comm<-host LoadLibrary(...)
[590412.008787s] DEBUG(runtime::session): comm->kern LoadRequest(...)
[590412.014576s] DEBUG(runtime::session): comm<-kern LoadReply(Ok(()))
[590412.019894s] DEBUG(runtime::session): comm->host LoadCompleted
[590412.028598s] DEBUG(runtime::session): comm<-host RunKernel
[590412.033385s] DEBUG(runtime::session): comm<-kern RpcSend { async: false, service: 3, tag: [79, 58, 108, 116, 4, 105, 105, 115, 102], data: 0x4ffffe8c }
[590412.046402s] DEBUG(runtime::session): comm->host RpcRequest { async: false }
[590412.053479s] DEBUG(proto_artiq::rpc_proto): send<3>(Object)->List(Tuple(Int32, Int32, String, Float64))
[590412.066134s] DEBUG(runtime::session): comm<-host RpcReply { tag: [108, 116, 4, 105, 105, 115, 102] }
[590412.074481s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffe80)
[590412.081033s] DEBUG(proto_artiq::rpc_proto): recv ...->List(Tuple(Int32, Int32, String, Float64))
[590412.089872s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(48))
[590412.096818s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffe40)
[590412.103283s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(1))
[590412.110129s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffe30)
[590412.116599s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(1))
[590412.123448s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffe20)
[590412.129900s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(0))
[590412.136800s] DEBUG(runtime::session): comm<-kern RpcSend { async: false, service: 2, tag: [115, 116, 4, 105, 105, 115, 102, 58, 110], data: 0x4ffffe00 }
[590412.149898s] DEBUG(runtime::session): comm->host RpcRequest { async: false }
[590412.156969s] DEBUG(proto_artiq::rpc_proto): send<2>(String, Tuple(Int32, Int32, String, Float64))->None
[590412.169541s] DEBUG(runtime::session): comm<-host RpcReply { tag: [110] }
[590412.175400s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffe98)
[590412.181960s] DEBUG(proto_artiq::rpc_proto): recv ...->None
[590412.187449s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(0))
[590412.194150s] DEBUG(runtime::session): comm<-kern RpcSend { async: false, service: 2, tag: [115, 116, 4, 105, 105, 115, 102, 58, 110], data: 0x4ffffdf0 }
[590412.207473s] DEBUG(runtime::session): comm->host RpcRequest { async: false }
[590412.214544s] DEBUG(proto_artiq::rpc_proto): send<2>(String, Tuple(Int32, Int32, String, Float64))->None
[590412.227046s] DEBUG(runtime::session): comm<-host RpcReply { tag: [110] }
[590412.232911s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffe98)
[590412.239463s] DEBUG(proto_artiq::rpc_proto): recv ...->None
[590412.244952s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(0))
[590412.251650s] DEBUG(runtime::session): comm<-kern RpcSend { async: false, service: 4, tag: [79, 58, 108, 116, 4, 105, 115, 102, 105], data: 0x4ffffde0 }
[590412.264889s] DEBUG(runtime::session): comm->host RpcRequest { async: false }
[590412.271960s] DEBUG(proto_artiq::rpc_proto): send<4>(Object)->List(Tuple(Int32, String, Float64, Int32))
[590412.284282s] DEBUG(runtime::session): comm<-host RpcReply { tag: [108, 116, 4, 105, 115, 102, 105] }
[590412.292616s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffde0)
[590412.299169s] DEBUG(proto_artiq::rpc_proto): recv ...->List(Tuple(Int32, String, Float64, Int32))
[590412.307995s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(24))
[590412.314948s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffdc0)
[590412.321398s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(1))
[590412.328265s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffdb0)
[590412.334721s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(0))
[590412.341619s] DEBUG(runtime::session): comm<-kern RpcSend { async: false, service: 2, tag: [115, 116, 4, 105, 115, 102, 105, 58, 110], data: 0x4ffffd90 }
[590412.354715s] DEBUG(runtime::session): comm->host RpcRequest { async: false }
[590412.361786s] DEBUG(proto_artiq::rpc_proto): send<2>(String, Tuple(Int32, String, Float64, Int32))->None
[590412.374641s] DEBUG(runtime::session): comm<-host RpcReply { tag: [110] }
[590412.380496s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffe98)
[590412.387059s] DEBUG(proto_artiq::rpc_proto): recv ...->None
[590412.392548s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(0))
[590412.399251s] DEBUG(runtime::session): comm<-kern RpcSend { async: false, service: 5, tag: [79, 58, 108, 116, 4, 105, 115, 102, 105], data: 0x4ffffd80 }
[590412.412485s] DEBUG(runtime::session): comm->host RpcRequest { async: false }
[590412.419557s] DEBUG(proto_artiq::rpc_proto): send<5>(Object)->List(Tuple(Int32, String, Float64, Int32))
[590412.432202s] DEBUG(runtime::session): comm<-host RpcReply { tag: [108, 116, 4, 105, 115, 102, 105] }
[590412.440536s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffd80)
[590412.447089s] DEBUG(proto_artiq::rpc_proto): recv ...->List(Tuple(Int32, String, Float64, Int32))
[590412.455917s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(48))
[590412.462870s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffd50)
[590412.469319s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(1))
[590412.476187s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffd40)
[590412.482654s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(1))
[590412.489504s] DEBUG(runtime::session): comm<-kern RpcRecvRequest(0x4ffffd30)
[590412.495959s] DEBUG(runtime::session): comm->kern RpcRecvReply(Ok(0))
[590412.502869s] DEBUG(runtime::session): comm<-kern Log(...)
[590412.508104s] DEBUG(runtime::session): comm<-kern Log(...)
[590412.513166s] INFO(kernel): panic at ksupport/lib.rs:533:5: Exception(LoadMisaligned) at PC 0x45060574
[590412.522738s] DEBUG(runtime::session): comm<-kern RunAborted
[590412.528011s] ERROR(runtime::session): session aborted: unexpected request RunAborted from kernel CPU
[590412.537444s] INFO(runtime::session): no connection, starting idle kernel
[590412.544356s] INFO(runtime::session): no idle kernel found