test_closedown fails on s390x architecture with Icarus

[TC01]

(I'm not actually sure this is a cocotb issue, but I thought I'd report it here anyway, just to be sure).

I've been maintaining cocotb packages in Fedora's repositories. Before 1.4, the package was a "noarch" package-- that is to say, it didn't contain any compiled code, since the simulator libraries had to be built by the user at runtime. I've finally gotten around to updating to cocotb 1.4; as part of that I've transitioned the package to an arched package-- with a build for each supported Fedora architecture, with the libraries pre-built. (We build Icarus Verilog on all architectures, so in theory, I think it makes sense to have builds on any architecture where iverilog is available).

To make sure that things work, from inside the Fedora buildsystem I run the test suite against Icarus. All the tests seem to pass on all the architectures... except for s390x, where one fails:

**Failure in testsuite: 'all' classname: 'test_closedown' testcase: 'test_failure_from_system_task' with parameters 'all'**

The logs from running test_closedown:

/usr/bin/iverilog -o sim_build/sim.vvp -D COCOTB_SIM=1 -s close_module -f sim_build/cmds.f -g2012   /builddir/build/BUILD/cocotb-1.4.0/tests/test_cases/test_closedown/../../../tests/designs/close_module/close_module.v
MODULE=test_closedown TESTCASE= TOPLEVEL=close_module TOPLEVEL_LANG=verilog \
        /usr/bin/vvp -M /builddir/build/BUILDROOT/python-cocotb-1.4.0-3.fc34.s390x/usr/lib64/python3.9/site-packages/cocotb/libs -m libcocotbvpi_icarus   sim_build/sim.vvp 
     -.--ns INFO     cocotb.gpi                         ..mbed/gpi_embed.cpp:74   in set_program_name_in_venv        Did not detect Python virtual environment. Using system-wide Python interpreter
     -.--ns INFO     cocotb.gpi                         ../gpi/GpiCommon.cpp:105  in gpi_print_registered_impl       VPI registered
     -.--ns INFO     cocotb.gpi                         ..mbed/gpi_embed.cpp:244  in embed_sim_init                  Python interpreter initialized and cocotb loaded!
     0.00ns INFO     cocotb                                      __init__.py:202  in _initialise_testbench           Running on Icarus Verilog version 10.3 (stable)
     0.00ns INFO     cocotb                                      __init__.py:208  in _initialise_testbench           Running tests with cocotb v1.4.0 from /builddir/build/BUILDROOT/python-cocotb-1.4.0-3.fc34.s390x/usr/lib64/python3.9/site-packages/cocotb
     0.00ns INFO     cocotb                                      __init__.py:229  in _initialise_testbench           Seeding Python random module with 1599234468
     0.00ns INFO     cocotb.regression                         regression.py:127  in __init__                        Found test test_closedown.test_failure_from_system_task
     0.00ns INFO     cocotb.regression                         regression.py:127  in __init__                        Found test test_closedown.test_after_system_task_fail
     0.00ns INFO     cocotb.regression                         regression.py:459  in _start_test                     Running test 1/2: test_failure_from_system_task
     0.00ns INFO     ..re_from_system_task.0x3ffb50d8fd0       decorators.py:255  in _advance                        Starting test: "test_failure_from_system_task"
                                                                                                                     Description: 
                                                                                                                         Allow the dut to call system tasks from verilog.
                                                                                                                         $fatal() will fail the test, and scheduler will cleanup forked coroutines.
                                                                                                                         
10000000.00ns ERROR    cocotb.regression                         regression.py:374  in _score_test                     Test passed but we expected a failure: test_failure_from_system_task (result was TestSuccess)
10000000.00ns INFO     cocotb.regression                         regression.py:459  in _start_test                     Running test 2/2: test_after_system_task_fail
10000000.00ns INFO     ..er_system_task_fail.0x3ffb5056f70       decorators.py:255  in _advance                        Starting test: "test_after_system_task_fail"
                                                                                                                       Description: 
                                                                                                                           Test to run after failed test.
                                                                                                                           
10000001.00ns INFO     cocotb.regression                         regression.py:361  in _score_test                     Test Passed: test_after_system_task_fail
10000001.00ns ERROR    cocotb.regression                         regression.py:475  in _log_test_summary               Failed 1 out of 2 tests (0 skipped)
10000001.00ns INFO     cocotb.regression                         regression.py:548  in _log_test_summary               ******************************************************************************************************
                                                                                                                       ** TEST                                          PASS/FAIL  SIM TIME(NS)  REAL TIME(S)  RATIO(NS/S) **
                                                                                                                       ******************************************************************************************************
                                                                                                                       ** test_closedown.test_failure_from_system_task    FAIL     10000000.00         25.12    398019.58  **
                                                                                                                       ** test_closedown.test_after_system_task_fail      PASS            1.00          0.00      8857.59  **
                                                                                                                       ******************************************************************************************************
                                                                                                                       
10000001.00ns INFO     cocotb.regression                         regression.py:565  in _log_sim_summary                *************************************************************************************
                                                                                                                       **                                 ERRORS : 1                                      **
                                                                                                                       *************************************************************************************
                                                                                                                       **                               SIM TIME : 10000001.00 NS                         **
                                                                                                                       **                              REAL TIME : 25.13 S                                **
                                                                                                                       **                        SIM / REAL TIME : 397903.49 NS/S                         **
                                                                                                                       *************************************************************************************

So... it seems like $fatal() didn't exit the simulator. Unfortunately, it's hard to know just from the log what exactly has happened here-- is this an issue with iverilog, or the cocotb interface to iverilog? This test passes on all the other architectures Fedora supports, but s390x is the only big endian architecture we support, so... that could be related.

I could see if I can get shell access to a s390x system through Fedora to try and debug this further (I suppose just seeing if $fatal works from Verilog code without cocotb would be a simple enough thing to try), or if there's something I can do through cocotb I'm happy to try that. But I wanted to file an issue somewhere so there was at least a record of the problem.

[ktbarrett]

I suppose just seeing if $fatal works from Verilog code without cocotb would be a simple enough thing to try

cocotb registers the $fatal system task to cleanly fail the current test. I doesn't exist without cocotb.

One thing you could do to see what happening is to increase logging verbosity and enable the scheduler debugging messages using COCOTB_LOG_LEVEL=DEBUG and COCOTB_SCHEDULER_DEBUG=1. Could you post the resulting log file?

s390x

That's a pretty niche architecture. Do you have any statistics on your package to see if anyone even downloaded cocotb on such a system? Is support on s390x necessary for Fedora to accept your package?

[TC01]

One thing you could do to see what happening is to increase logging verbosity and enable the scheduler debugging messages using COCOTB_LOG_LEVEL=DEBUG and COCOTB_SCHEDULER_DEBUG=1. Could you post the resulting log file?

Sure, I'll give this a try and post the output.

That's a pretty niche architecture. Do you have any statistics on your package to see if anyone even downloaded cocotb on such a system? Is support on s390x necessary for Fedora to accept your package?

No, and in fact I've already worked around the problem by disabling the build on s390x (at least for now). I think "this is too weird an architecture to support" is a perfectly acceptable answer (I can't imagine many people are doing ASIC/FPGA development using open source tools on an IBM mainframe!), but since iverilog (and ghdl, actually) both seem to be built for it, and since only one test failed, I thought it would be worth investigating at least a little bit.

[ktbarrett]

If it's only the one test that fails, you could ship it anyway. Simulators that aren't Icarus (on x86_64) all have at least 1 failing test, so even considering that issue, it's still high quality, relatively.

[eric-wieser]

We would also accept a PR that just skips that test on that platform, I think.

[TC01]

Okay, I took another look at this-- I tried running the build with the debugging turned on. Here's the initial log where we initialize test_failure_from_system_task in this test case:

     0.00ns INFO     ..re_from_system_task.0x3ff9d2d5ac0       decorators.py:255  in _advance                        Starting test: "test_failure_from_system_task"
                                                                                                                     Description: 
                                                                                                                         Allow the dut to call system tasks from verilog.
                                                                                                                         $fatal() will fail the test, and scheduler will cleanup forked coroutines.
                                                                                                                         
     0.00ns DEBUG    cocotb.gpi                                GpiCommon.cpp:301  in __gpi_get_handle_by_name        Searching for clk
     0.00ns DEBUG    cocotb.gpi                                GpiCommon.cpp:312  in __gpi_get_handle_by_name        Checking if clk is native through implementation VPI
     0.00ns DEBUG    cocotb.gpi                                 VpiCbHdl.cpp:286  in initialise                      VPI: clk initialized with 1 elements
     0.00ns DEBUG    cocotb.gpi                                  VpiImpl.cpp:244  in create_gpi_obj_from_handle      VPI: Created GPI object from type vpiNet(36)
     0.00ns DEBUG    cocotb.gpi                                GpiCommon.cpp:324  in __gpi_get_handle_by_name        Found clk via VPI
     0.00ns DEBUG    cocotb.gpi                                GpiCommon.cpp:51   in check_and_store                 Checking close_module.clk exists
     0.00ns DEBUG    cocotb.clk                                    handle.py:94   in __init__                        Created
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:666  in add                             Adding new coroutine Clock.start
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:756  in schedule                        Scheduling with Value(None)
     0.00ns DEBUG    cocotb.gpi                                   gpi_priv.h:101  in get_num_elems                   clk has 1 elements
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:666  in add                             Adding new coroutine Scheduler._do_writes
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:756  in schedule                        Scheduling with Value(None)
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:762  in schedule                        Coroutine Scheduler._do_writes yielded <<Event at 0x3ff9de548e0>.wait() at 0x3ff9d2df0c0> (mode 1)
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:762  in schedule                        Coroutine Clock.start yielded <Timer of 50000.00ps at 0x3ff9e158540> (mode 1)
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:666  in add                             Adding new coroutine clock_mon
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:756  in schedule                        Scheduling with Value(None)
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:762  in schedule                        Coroutine clock_mon yielded RisingEdge(ModifiableObject(close_module.clk)) (mode 1)
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:666  in add                             Adding new coroutine run_external
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:756  in schedule                        Scheduling with Value(None)
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:762  in schedule                        Coroutine run_external yielded <<Event at 0x3ff9d2d5610>.wait() at 0x3ff9d2df6c0> (mode 1)
     0.00ns DEBUG    ..external.thead.None.0x3ff9d2d5850        scheduler.py:111  in _propagate_state                Changing state from 0 -> 1 from <_MainThread(MainThread, started 4396412790576)>
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:616  in execute_external                Execution of external routine done <Thread(test_read_thread, started 4396379273328)>
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:800  in schedule                        Blocking from <_MainThread(MainThread, started 4396412790576)> on <Thread(test_read_thread, started 4396379273328)>
     0.00ns DEBUG    ..external.thead.None.0x3ff9d2d5850        scheduler.py:136  in thread_wait                     Waiting for the condition lock <_MainThread(MainThread, started 4396412790576)>
     0.00ns DEBUG    ..external.thead.None.0x3ff9d2d5850        scheduler.py:117  in thread_done                     Thread finished from <Thread(test_read_thread, started 4396379273328)>
     0.00ns DEBUG    ..external.thead.None.0x3ff9d2d5850        scheduler.py:111  in _propagate_state                Changing state from 1 -> 3 from <Thread(test_read_thread, started 4396379273328)>
     0.00ns DEBUG    ..external.thead.None.0x3ff9d2d5850        scheduler.py:144  in thread_wait                     Thread <Thread(test_read_thread, stopped 4396379273328)> has exited from <_MainThread(MainThread, started 4396412790576)>
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:803  in schedule                        Back from wait on self <_MainThread(MainThread, started 4396412790576)> with newstate 3
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:762  in schedule                        Coroutine test_failure_from_system_task yielded <Timer of 10000000000.00ps at 0x3ff9d2dfbc0> (mode 1)
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:446  in _event_loop                     Scheduled coroutine test_failure_from_system_task
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:451  in _event_loop                     Scheduling pending event <Event at 0x3ff9d2d5610>
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:432  in _event_loop                     1 pending coroutines for event <<Event at 0x3ff9de548e0>.wait() at 0x3ff9d2df0c0>
                                                                                                                     	Scheduler._do_writes
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:443  in _event_loop                     Scheduling coroutine Scheduler._do_writes
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:756  in schedule                        Scheduling with Value(<<Event at 0x3ff9de548e0>.wait() at 0x3ff9d2df0c0>)
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:762  in schedule                        Coroutine Scheduler._do_writes yielded ReadWrite() (mode 1)
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:446  in _event_loop                     Scheduled coroutine Scheduler._do_writes
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:432  in _event_loop                     1 pending coroutines for event <<Event at 0x3ff9d2d5610>.wait() at 0x3ff9d2df6c0>
                                                                                                                     	run_external
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:443  in _event_loop                     Scheduling coroutine run_external
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:756  in schedule                        Scheduling with Value(<<Event at 0x3ff9d2d5610>.wait() at 0x3ff9d2df6c0>)
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:767  in schedule                        Coroutine run_external completed with Value(None)
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:446  in _event_loop                     Scheduled coroutine run_external
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:465  in _event_loop                     All coroutines scheduled, handing control back to simulator
     0.00ns DEBUG    cocotb.gpi                                gpi_embed.cpp:310  in embed_sim_init                  _initialise_testbench successful
     0.00ns DEBUG    cocotb.gpi                                gpi_embed.cpp:327  in embed_sim_init                  Returning to simulator
     0.00ns DEBUG    cocotb.gpi                                 GpiCbHdl.cpp:96   in run_callback                    Generic run_callback
     0.00ns DEBUG    cocotb.gpi                          simulatormodule.cpp:186  in handle_gpi_callback             Returning to Python
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:372  in _event_loop                     Trigger fired: ReadWrite()
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:432  in _event_loop                     1 pending coroutines for event ReadWrite()
                                                                                                                     	Scheduler._do_writes
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:443  in _event_loop                     Scheduling coroutine Scheduler._do_writes
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:756  in schedule                        Scheduling with Value(ReadWrite())
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:762  in schedule                        Coroutine Scheduler._do_writes yielded <<Event at 0x3ff9de548e0>.wait() at 0x3ff9d2d7480> (mode 1)
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:446  in _event_loop                     Scheduled coroutine Scheduler._do_writes
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:465  in _event_loop                     All coroutines scheduled, handing control back to simulator
     0.00ns DEBUG    cocotb.gpi                          simulatormodule.cpp:244  in handle_gpi_callback             Returning to simulator
     0.00ns DEBUG    cocotb.gpi                                 GpiCbHdl.cpp:98   in run_callback                    Generic run_callback done
     0.00ns DEBUG    cocotb.gpi                          simulatormodule.cpp:186  in handle_gpi_callback             Returning to Python
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:372  in _event_loop                     Trigger fired: RisingEdge(ModifiableObject(close_module.clk))
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:432  in _event_loop                     1 pending coroutines for event RisingEdge(ModifiableObject(close_module.clk))
                                                                                                                     	clock_mon
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:443  in _event_loop                     Scheduling coroutine clock_mon
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:756  in schedule                        Scheduling with Value(RisingEdge(ModifiableObject(close_module.clk)))
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:767  in schedule                        Coroutine clock_mon completed with Value(None)
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:446  in _event_loop                     Scheduled coroutine clock_mon
     0.00ns DEBUG    cocotb.scheduler                           scheduler.py:465  in _event_loop                     All coroutines scheduled, handing control back to simulator
     0.00ns DEBUG    cocotb.gpi                          simulatormodule.cpp:244  in handle_gpi_callback             Returning to simulator
     0.00ns DEBUG    cocotb.gpi                                 GpiCbHdl.cpp:96   in run_callback                    Generic run_callback

It looks like every 50 ns, the following happens, with the test eventually timing out at a whopping 10000000.00ns (which I should probably have realized from looking at the log above).

   100.00ns DEBUG    cocotb.gpi                          simulatormodule.cpp:186  in handle_gpi_callback             Returning to Python
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:372  in _event_loop                     Trigger fired: <Timer of 50000.00ps at 0x3ff9e158540>
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:432  in _event_loop                     1 pending coroutines for event <Timer of 50000.00ps at 0x3ff9e158540>
                                                                                                                     	Clock.start
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:443  in _event_loop                     Scheduling coroutine Clock.start
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:756  in schedule                        Scheduling with Value(<Timer of 50000.00ps at 0x3ff9e158540>)
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:762  in schedule                        Coroutine Clock.start yielded <Timer of 50000.00ps at 0x3ff9e158540> (mode 1)
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:446  in _event_loop                     Scheduled coroutine Clock.start
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:432  in _event_loop                     1 pending coroutines for event <<Event at 0x3ff9de548e0>.wait() at 0x3ff9d2d7bc0>
                                                                                                                     	Scheduler._do_writes
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:443  in _event_loop                     Scheduling coroutine Scheduler._do_writes
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:756  in schedule                        Scheduling with Value(<<Event at 0x3ff9de548e0>.wait() at 0x3ff9d2d7bc0>)
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:762  in schedule                        Coroutine Scheduler._do_writes yielded ReadWrite() (mode 1)
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:446  in _event_loop                     Scheduled coroutine Scheduler._do_writes
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:465  in _event_loop                     All coroutines scheduled, handing control back to simulator
   100.00ns DEBUG    cocotb.gpi                          simulatormodule.cpp:244  in handle_gpi_callback             Returning to simulator
   100.00ns DEBUG    cocotb.gpi                                 GpiCbHdl.cpp:98   in run_callback                    Generic run_callback done
   100.00ns DEBUG    cocotb.gpi                                 GpiCbHdl.cpp:96   in run_callback                    Generic run_callback
   100.00ns DEBUG    cocotb.gpi                          simulatormodule.cpp:186  in handle_gpi_callback             Returning to Python
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:372  in _event_loop                     Trigger fired: ReadWrite()
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:432  in _event_loop                     1 pending coroutines for event ReadWrite()
                                                                                                                     	Scheduler._do_writes
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:443  in _event_loop                     Scheduling coroutine Scheduler._do_writes
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:756  in schedule                        Scheduling with Value(ReadWrite())
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:762  in schedule                        Coroutine Scheduler._do_writes yielded <<Event at 0x3ff9de548e0>.wait() at 0x3ff9d2d7b40> (mode 1)
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:446  in _event_loop                     Scheduled coroutine Scheduler._do_writes
   100.00ns DEBUG    cocotb.scheduler                           scheduler.py:465  in _event_loop                     All coroutines scheduled, handing control back to simulator
   100.00ns DEBUG    cocotb.gpi                          simulatormodule.cpp:244  in handle_gpi_callback             Returning to simulator
   100.00ns DEBUG    cocotb.gpi                                 GpiCbHdl.cpp:98   in run_callback                    Generic run_callback done
   100.00ns DEBUG    cocotb.gpi                                 GpiCbHdl.cpp:96   in run_callback                    Generic run_callback

I'm not sure how helpful this is, but it does seem to confirm that $fatal() is failing to actually stop the simulation, and then the test eventually times out after a very long time has passed.

[ktbarrett]

The logs you posted seem to indicate that the $finish() task is never called by the HDL. I think we will need @bluecmd's assistance tracking down the root cause. Is it our registering of the task that doesn't work? Or is is Icarus's calling of it that doesn't occur / doesn't work?