cocotb: Bad file descriptor logging error on Windows with Modelsim

Hi. I started to use cocotb with Modelsim and around 50% of the cases I get --- Logging error --- with OSError: [Errno 9] Bad file descriptor when I run make SIM=modelsim. In this case the powershell output is scrambled but the test cases run successful. The other 50% everything works as expected.

Installation setup

Windows 10 64-bit (v2004), miniconda 4.8.3 (python 3.8.3) and cocotb 1.4.0 installation according to https://docs.cocotb.org/en/stable/install.html all in 64-bit. Modelsim DE-64 vsim 10.7a (64-bit)

Test setup

I run cocotb\examples\dff wih make SIM=modelsim as an example but I experience the same issue with other/own tests as well. The test run in the Anaconda Powershell Prompt The following section shows the back to back powershell output of two make SIM=modelsim calls

logging error with scrambled output
everything works as expected

The outcome is not predictable, sometime the first run of make is successful after clean up the build artifacts. Sometimes it’s successful multiple times in a row. Sometimes it scrambles multiple times.

Powershell output

(base) PS C:\workdir\Arbeitspaket\2020-08-02_cocotb\examples\dff\tests> make SIM=modelsim
/usr/bin/make results.xml
make[1]: Entering directory '/c/workdir/Arbeitspaket/2020-08-02_cocotb/examples/dff/tests'
mkdir -p sim_build
set -o pipefail; MODULE=dff_cocotb TESTCASE= TOPLEVEL="work.dff" \
GPI_EXTRA= TOPLEVEL_LANG=vhdl \
/c/MentorGraphics/modelsim_dlx64_10.7a/win64pe/vsim -c -64  -do sim_build/runsim.do  2>&1 | tee sim_build/sim.log
Reading C:/MentorGraphics/modelsim_dlx64_10.7a/tcl/vsim/pref.tcl

# 10.7a

# do sim_build/runsim.do
# Model Technology ModelSim DE-64 vmap 10.7a Lib Mapping Utility 2018.03 Mar 27 2018
# vmap -c
# Copying C:/MentorGraphics/modelsim_dlx64_10.7a/win64pe/../modelsim.ini to modelsim.ini
# Model Technology ModelSim DE-64 vmap 10.7a Lib Mapping Utility 2018.03 Mar 27 2018
# vmap work sim_build/work
# Modifying modelsim.ini
# Model Technology ModelSim DE-64 vcom 10.7a Compiler 2018.03 Mar 27 2018
# Start time: 22:51:45 on Aug 10,2020
# vcom -work work "+acc" C:/workdir/Arbeitspaket/2020-08-02_cocotb/examples/dff/hdl/dff.vhdl
# -- Loading package STANDARD
# -- Loading package TEXTIO
# -- Loading package std_logic_1164
# -- Compiling entity dff
# -- Compiling architecture rtl of dff
# End time: 22:51:45 on Aug 10,2020, Elapsed time: 0:00:00
# Errors: 0, Warnings: 0
# ** Warning: (vsim-159) Mode option -64 is not supported in this context and will be ignored.
# vsim -onfinish exit -foreign "cocotb_init C:/programdata/miniconda3/lib/site-packages/cocotb/libs/libcocotbfli_modelsim.dll" sim_build/work.dff
# Start time: 22:51:45 on Aug 10,2020
# //  ModelSim DE-64 10.7a Mar 27 2018
# //
# //  Copyright 1991-2018 Mentor Graphics Corporation
# //  All Rights Reserved.
# //
# //  ModelSim DE-64 and its associated documentation contain trade
# //  secrets and commercial or financial information that are the property of
# //  Mentor Graphics Corporation and are privileged, confidential,
# //  and exempt from disclosure under the Freedom of Information Act,
# //  5 U.S.C. Section 552. Furthermore, this information
# //  is prohibited from disclosure under the Trade Secrets Act,
# //  18 U.S.C. Section 1905.
# //
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\__init__.py", line 188, in _initialise_testbench
    _setup_logging()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\__init__.py", line 86, in _setup_logging
    log.warning("Failed to ensure that stdout is line buffered", exc_info=_stdout_buffer_result)
Message: 'Failed to ensure that stdout is line buffered'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\__init__.py", line 188, in _initialise_testbench
    _setup_logging()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\__init__.py", line 89, in _setup_logging
    log.warning("Some stack traces may not appear because of this.")
Message: 'Some stack traces may not appear because of this.'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\__init__.py", line 202, in _initialise_testbench
    cocotb.log.info("Running on {} version {}".format(SIM_NAME, SIM_VERSION))
Message: 'Running on ModelSim DE-64 version 10.7a 2018.03'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\__init__.py", line 208, in _initialise_testbench
    log.info("Running tests with cocotb v%s from %s" %
Message: 'Running tests with cocotb v1.4.0 from C:\\programdata\\miniconda3\\lib\\site-packages\\cocotb'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\__init__.py", line 229, in _initialise_testbench
    log.info("Seeding Python random module with %d" % (RANDOM_SEED))
Message: 'Seeding Python random module with 1597092706'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\__init__.py", line 246, in _initialise_testbench
    regression_manager = RegressionManager.from_discovery(dut)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 154, in from_discovery
    return cls(dut, tests, hooks)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 127, in __init__
    self.log.info("Found test {}.{}".format(test.__module__, test.__qualname__))
Message: 'Found test dff_cocotb.run_test_001'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\__init__.py", line 247, in _initialise_testbench
    regression_manager.execute()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 450, in execute
    return self._start_test()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 459, in _start_test
    self.log.info("%sRunning test %d/%d:%s %s" %
Message: 'Running test 1/1: run_test_001'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\__init__.py", line 247, in _initialise_testbench
    regression_manager.execute()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 450, in execute
    return self._start_test()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 470, in _start_test
    cocotb.scheduler.add_test(self._test_task)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 679, in add_test
    self._resume_coro_upon(
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 546, in _resume_coro_upon
    trigger.prime(self.react)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\triggers.py", line 554, in prime
    callback(self)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 351, in react
    self._event_loop(trigger)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 445, in _event_loop
    self.schedule(coro, trigger=trigger)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 761, in schedule
    result = coroutine._advance(send_outcome)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\decorators.py", line 255, in _advance
    self.log.info("Starting test: \"%s\"\nDescription: %s" %
Message: 'Starting test: "run_test_001"\nDescription: Automatically generated test\n\n'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\__init__.py", line 247, in _initialise_testbench
    regression_manager.execute()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 450, in execute
    return self._start_test()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 470, in _start_test
    cocotb.scheduler.add_test(self._test_task)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 679, in add_test
    self._resume_coro_upon(
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 546, in _resume_coro_upon
    trigger.prime(self.react)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\triggers.py", line 554, in prime
    callback(self)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 351, in react
    self._event_loop(trigger)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 445, in _event_loop
    self.schedule(coro, trigger=trigger)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 761, in schedule
    result = coroutine._advance(send_outcome)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\decorators.py", line 260, in _advance
    return super(RunningTest, self)._advance(outcome)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\decorators.py", line 148, in _advance
    return outcome.send(self._coro)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\outcomes.py", line 36, in send
    return gen.send(self.value)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 596, in _my_test
    await function(dut, *args, **kwargs)
  File "C:\workdir\Arbeitspaket\2020-08-02_cocotb\examples\dff\tests\dff_cocotb.py", line 137, in run_test
    tb = DFF_TB(dut, init_val=BinaryValue(0))
  File "C:\workdir\Arbeitspaket\2020-08-02_cocotb\examples\dff\tests\dff_cocotb.py", line 97, in __init__
    self.scoreboard.add_interface(self.output_mon, self.expected_output)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scoreboard.py", line 216, in add_interface
    self.log.info("Created with reorder_depth %d" % reorder_depth)
Message: 'Created with reorder_depth 0'
Arguments: ()
# Loading std.standard
# Loading std.textio(body)
# Loading ieee.std_logic_1164(body)
# Loading sim_build/work.dff(rtl)
# Loading C:/programdata/miniconda3/lib/site-packages/cocotb/libs/libcocotbfli_modelsim.dll
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 325, in _test_completed
    cocotb.regression_manager.handle_result(test)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 295, in handle_result
    self._record_result(
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 426, in _record_result
    test_pass, sim_failed = self._score_test(test, outcome)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 361, in _score_test
    self.log.info("Test Passed: %s" % test.__qualname__)
Message: 'Test Passed: run_test_001'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 325, in _test_completed
    cocotb.regression_manager.handle_result(test)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 301, in handle_result
    self.execute()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 446, in execute
    return self.tear_down()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 253, in tear_down
    self._log_test_summary()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 478, in _log_test_summary
    self.log.info("Passed %d tests (%d skipped)" %
Message: 'Passed 1 tests (0 skipped)'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 325, in _test_completed
    cocotb.regression_manager.handle_result(test)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 301, in handle_result
    self.execute()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 446, in execute
    return self.tear_down()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 253, in tear_down
    self._log_test_summary()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 548, in _log_test_summary
    self.log.info(summary)
Message: '*********************************************************************************\n** TEST                     PASS/FAIL  SIM TIME(NS)  REAL TIME(S)  RATIO(NS/S) **\n*********************************************************************************\n** dff_cocotb.run_test_001    PASS      1005001.00          0.02   40246328.56  **\n*********************************************************************************\n'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 325, in _test_completed
    cocotb.regression_manager.handle_result(test)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 301, in handle_result
    self.execute()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 446, in execute
    return self.tear_down()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 254, in tear_down
    self._log_sim_summary()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 565, in _log_sim_summary
    self.log.info(summary)
Message: '*************************************************************************************\n**                                 ERRORS : 0                                      **\n*************************************************************************************\n**                               SIM TIME : 1005001.00 NS                          **\n**                              REAL TIME : 0.07 S                                 **\n**                        SIM / REAL TIME : 14160392.21 NS/S                       **\n*************************************************************************************\n'
Arguments: ()
--- Logging error ---
Traceback (most recent call last):
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1085, in emit
    self.flush()
  File "C:\programdata\miniconda3\lib\logging\__init__.py", line 1065, in flush
    self.stream.flush()
OSError: [Errno 9] Bad file descriptor
Call stack:
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\scheduler.py", line 325, in _test_completed
    cocotb.regression_manager.handle_result(test)
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 301, in handle_result
    self.execute()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 446, in execute
    return self.tear_down()
  File "C:\programdata\miniconda3\lib\site-packages\cocotb\regression.py", line 255, in tear_down
    self.log.info("Shutting down...")
Message: 'Shutting down...'
Arguments: ()
Exception ignored in: <_io.TextIOWrapper name='<stdout>' mode='w' encoding='cp1252'>
OSError: [Errno 9] Bad file descriptor
# Simulation halt requested by foreign interface.
# End time: 22:51:46 on Aug 10,2020, Elapsed time: 0:00:01
# Errors: 0, Warnings: 1
make[1]: Leaving directory '/c/workdir/Arbeitspaket/2020-08-02_cocotb/examples/dff/tests'
(base) PS C:\workdir\Arbeitspaket\2020-08-02_cocotb\examples\dff\tests>

(base) PS C:\workdir\Arbeitspaket\2020-08-02_cocotb\examples\dff\tests> make SIM=modelsim
/usr/bin/make results.xml
make[1]: Entering directory '/c/workdir/Arbeitspaket/2020-08-02_cocotb/examples/dff/tests'
mkdir -p sim_build
set -o pipefail; MODULE=dff_cocotb TESTCASE= TOPLEVEL="work.dff" \
GPI_EXTRA= TOPLEVEL_LANG=vhdl \
/c/MentorGraphics/modelsim_dlx64_10.7a/win64pe/vsim -c -64  -do sim_build/runsim.do  2>&1 | tee sim_build/sim.log
Reading C:/MentorGraphics/modelsim_dlx64_10.7a/tcl/vsim/pref.tcl

# 10.7a

# do sim_build/runsim.do
# Model Technology ModelSim DE-64 vmap 10.7a Lib Mapping Utility 2018.03 Mar 27 2018
# vmap -c
# Copying C:/MentorGraphics/modelsim_dlx64_10.7a/win64pe/../modelsim.ini to modelsim.ini
# Model Technology ModelSim DE-64 vmap 10.7a Lib Mapping Utility 2018.03 Mar 27 2018
# vmap work sim_build/work
# Modifying modelsim.ini
# Model Technology ModelSim DE-64 vcom 10.7a Compiler 2018.03 Mar 27 2018
# Start time: 22:53:42 on Aug 10,2020
# vcom -work work "+acc" C:/workdir/Arbeitspaket/2020-08-02_cocotb/examples/dff/hdl/dff.vhdl
# -- Loading package STANDARD
# -- Loading package TEXTIO
# -- Loading package std_logic_1164
# -- Compiling entity dff
# -- Compiling architecture rtl of dff
# End time: 22:53:42 on Aug 10,2020, Elapsed time: 0:00:00
# Errors: 0, Warnings: 0
# ** Warning: (vsim-159) Mode option -64 is not supported in this context and will be ignored.
# vsim -onfinish exit -foreign "cocotb_init C:/programdata/miniconda3/lib/site-packages/cocotb/libs/libcocotbfli_modelsim.dll" sim_build/work.dff
# Start time: 22:53:42 on Aug 10,2020
# //  ModelSim DE-64 10.7a Mar 27 2018
# //
# //  Copyright 1991-2018 Mentor Graphics Corporation
# //  All Rights Reserved.
# //
# //  ModelSim DE-64 and its associated documentation contain trade
# //  secrets and commercial or financial information that are the property of
# //  Mentor Graphics Corporation and are privileged, confidential,
# //  and exempt from disclosure under the Freedom of Information Act,
# //  5 U.S.C. Section 552. Furthermore, this information
# //  is prohibited from disclosure under the Trade Secrets Act,
# //  18 U.S.C. Section 1905.
# //
# Loading std.standard
# Loading std.textio(body)
# Loading ieee.std_logic_1164(body)
# Loading sim_build/work.dff(rtl)
# Loading C:/programdata/miniconda3/lib/site-packages/cocotb/libs/libcocotbfli_modelsim.dll
#      -.--ns INFO     cocotb.gpi                         ..ib\fli\FliImpl.cpp:1063 in cocotb_init                     cocotb_init called
#
#
#
#      -.--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       FLI 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 ModelSim DE-64 version 10.7a 2018.03
#
#      0.00ns INFO     cocotb                                      __init__.py:208  in _initialise_testbench           Running tests with cocotb v1.4.0 from C:\programdata\miniconda3\lib\site-packages\cocotb
#
#      0.00ns INFO     cocotb                                      __init__.py:229  in _initialise_testbench           Seeding Python random module with 1597092823
#
#      0.00ns INFO     cocotb.regression                         regression.py:127  in __init__                        Found test dff_cocotb.run_test_001
#
#      0.00ns INFO     cocotb.regression                         regression.py:459  in _start_test                     Running test 1/1: run_test_001
#
#      0.00ns INFO     cocotb.test.run_test_001.0xec4e940        decorators.py:255  in _advance                        Starting test: "run_test_001"
#
#                                                                                                                      Description: Automatically generated test
#
#
#
#
#
#      0.00ns INFO     cocotb.scoreboard.dff                     scoreboard.py:216  in add_interface                   Created with reorder_depth 0
#
# 1005001.00ns INFO     cocotb.regression                         regression.py:361  in _score_test                     Test Passed: run_test_001
#
# 1005001.00ns INFO     cocotb.regression                         regression.py:478  in _log_test_summary               Passed 1 tests (0 skipped)
#
# 1005001.00ns INFO     cocotb.regression                         regression.py:548  in _log_test_summary               *********************************************************************************
#
#                                                                                                                       ** TEST                     PASS/FAIL  SIM TIME(NS)  REAL TIME(S)  RATIO(NS/S) **
#
#                                                                                                                       *********************************************************************************
#
#                                                                                                                       ** dff_cocotb.run_test_001    PASS      1005001.00          0.02   45677254.07  **
#
#                                                                                                                       *********************************************************************************
#
#
#
# 1005001.00ns INFO     cocotb.regression                         regression.py:565  in _log_sim_summary                *************************************************************************************
#
#                                                                                                                       **                                 ERRORS : 0                                      **
#
#                                                                                                                       *************************************************************************************
#
#                                                                                                                       **                               SIM TIME : 1005001.00 NS                          **
#
#                                                                                                                       **                              REAL TIME : 0.05 S                                 **
#
#                                                                                                                       **                        SIM / REAL TIME : 20509415.77 NS/S                       **
#
#                                                                                                                       *************************************************************************************
#
#
#
# 1005001.00ns INFO     cocotb.regression                         regression.py:255  in tear_down                       Shutting down...
#
# Simulation halt requested by foreign interface.
# End time: 22:53:43 on Aug 10,2020, Elapsed time: 0:00:01
# Errors: 0, Warnings: 1
make[1]: Leaving directory '/c/workdir/Arbeitspaket/2020-08-02_cocotb/examples/dff/tests'
(base) PS C:\workdir\Arbeitspaket\2020-08-02_cocotb\examples\dff\tests>
(base) PS C:\workdir\Arbeitspaket\2020-08-02_cocotb\examples\dff\tests> conda --version
conda 4.8.3
(base) PS C:\workdir\Arbeitspaket\2020-08-02_cocotb\examples\dff\tests> cocotb-config --version
1.4.0
(base) PS C:\workdir\Arbeitspaket\2020-08-02_cocotb\examples\dff\tests> python --version
Python 3.8.3
(base) PS C:\workdir\Arbeitspaket\2020-08-02_cocotb\examples\dff\tests> vsim -version
Model Technology ModelSim DE-64 vsim 10.7a Simulator 2018.03 Mar 27 2018
(base) PS C:\workdir\Arbeitspaket\2020-08-02_cocotb\examples\dff\tests> Get-ComputerInfo  | select windowsversion,windowsproductname,osarchitecture

WindowsVersion WindowsProductName OsArchitecture
-------------- ------------------ --------------
2004           Windows 10 Pro     64-bit


(base) PS C:\workdir\Arbeitspaket\2020-08-02_cocotb\examples\dff\tests>

Attachment

sim.log from

About this issue

Original URL
State: closed
Created 4 years ago
Comments: 25 (16 by maintainers)

Most upvoted comments

I would recommend these docs for moving stdout logs to a file and not using print.

ktbarrett on Feb 2, 2022

This may not work for everyone, but I worked around this problem in cocotb 1.6 by simply redirecting the logger to use mti_PrintMessage:

import logging
from cocotb.log import SimLogFormatter, SimTimeContextFilter

class ModelsimLogHandler(logging.Handler):
    """
    This works around a very stupid and hard-to-debug issue documented here:
    https://github.com/cocotb/cocotb/issues/2015

    This is a brute-force solution which instead of actually fixing the
    problem merely avoids it by redirecting output into modelsim's window
    via the appropriate FLI call.
    """

    def __init__(self):
        super().__init__()
        import ctypes

        mti = ctypes.WinDLL("mtipli.dll")

        def wrapper(fn, restype, *argtypes):
            fn.restype = restype
            fn.argtypes = argtypes
            return fn

        self._mti_PrintMessage = wrapper(mti.mti_PrintMessage, None, ctypes.c_char_p)

    def emit(self, record):
        try:
            msg = self.format(record)
            self._mti_PrintMessage(msg.encode("latin-1"))
        except RecursionError:  # Copy-paste from logging library
            raise
        except Exception:
            self.handleError(record)


def fix_modelsim_log_bug():
    hdlr = ModelsimLogHandler()
    hdlr.addFilter(SimTimeContextFilter())
    hdlr.setFormatter(SimLogFormatter())
    logging.getLogger().handlers = [hdlr]

I call fix_modelsim_log_bug at the start of each of my tests. Putting it directly in the file to be executed sequentially wouldn’t work since the logger is reset between the time the python is parsed and when the first test case runs.

Best I can tell from my exploration in modelsim SE 2020.4, there’s some kind of weird race condition in modelsim where if it doesn’t print out the “Loading …” lines when it elaborates, all the further logging calls (which simply go to stdout) fail. I strongly suspect that modelsim internally is closing stdout, perhaps after duplicating it. I’ve tried a few ways of intercepting stdout before modelsim bungles it, but so far to no avail, hence this band-aid.

kcuzner on Feb 1, 2022

@manunited10 seems like something like this would be your best bet: https://stackoverflow.com/a/4675744/1124529

kcuzner on Feb 2, 2022

This error is in OP’s log as well. The error comes after a simple print function. I commented that out and it goes to another print (on unsuccessful runs). While some googling says the error is due to writing to a file which is already closed, I checked my entire code and there is no such thing. Besides 50-60% of the time it runs successfully (not a permanent error).

Print by default will write to stdout, which has likely been screwed up by modelsim, so that’s why it’s failing. You need to replace your print calls with calls to mti_PrintMessage or as @ktbarrett suggests, write to a file instead (there is a file argument to print that can be used for this, see the docs). Or, you can replace your print with calls to logging.info or something.

kcuzner on Feb 2, 2022