Threading harms indentation in debug log file

A simple FOR loop:

FOR    ${index}    IN RANGE    0    2
   Log     I am index ${index} of thread 1
END

causes the following log output:

INFO - +-- START FOR: ${index} IN RANGE [ 0 | 2 ] [ ]
INFO - +--- START ITERATION: ${index} = 0 [ ]
INFO - +---- START KEYWORD: BuiltIn.Log [ I am index ${index} ]
INFO - I am index 0
INFO - +---- END KEYWORD: BuiltIn.Log (0)
INFO - +--- END ITERATION: ${index} = 0 (0)
INFO - +--- START ITERATION: ${index} = 1 [ ]
INFO - +---- START KEYWORD: BuiltIn.Log [ I am index ${index} ]
INFO - I am index 1
INFO - +---- END KEYWORD: BuiltIn.Log (0)
INFO - +--- END ITERATION: ${index} = 1 (0)
INFO - +-- END FOR: ${index} IN RANGE [ 0 | 2 ] (0)

It can be seen that the indentation of a start of something is aligned to the indentation of the corresponding end of this something.

Now the same in two threads:

THREAD    TEST_THREAD_1     False
   FOR    ${index}    IN RANGE    0    2
      Log     I am index ${index} of thread 1
   END
END

THREAD    TEST_THREAD_2     False
   FOR    ${index}    IN RANGE    0    2
      Log     I am index ${index} of thread 2
   END
END

Log output:

INFO - + START SUITE: Test.Threading [ ]
======================================================
INFO - +- START TEST: Threading Test [ ]
------------------------------------------------------
INFO - +-- START THREAD: TEST_THREAD_1 [ ]
INFO - +--- START FOR: ${index} IN RANGE [ 0 | 2 ] [ ]
INFO - +--- START THREAD: TEST_THREAD_2 [ ]
INFO - +----- START FOR: ${index} IN RANGE [ 0 | 2 ] [ ]
INFO - +------ START ITERATION: ${index} = 0 [ ]
INFO - +------ START ITERATION: ${index} = 0 [ ]
INFO - +------- START KEYWORD: BuiltIn.Log [ I am index ${index} of thread 1 ]
INFO - +-------- START KEYWORD: BuiltIn.Log [ I am index ${index} of thread 2 ]
INFO - +-------- END KEYWORD: BuiltIn.Log (1)
INFO - +-------- END KEYWORD: BuiltIn.Log (1)
INFO - +------- END ITERATION: ${index} = 0 (1)
INFO - +------ END ITERATION: ${index} = 0 (1)
INFO - +------ START ITERATION: ${index} = 1 [ ]
INFO - +------ START ITERATION: ${index} = 1 [ ]
INFO - +------- START KEYWORD: BuiltIn.Log [ I am index ${index} of thread 1 ]
INFO - +-------- START KEYWORD: BuiltIn.Log [ I am index ${index} of thread 2 ]
INFO - +-------- END KEYWORD: BuiltIn.Log (0)
INFO - +-------- END KEYWORD: BuiltIn.Log (1)
INFO - +------- END ITERATION: ${index} = 1 (2)
------------------------------------------------------
INFO - +------ END ITERATION: ${index} = 1 (1)
INFO - +---- END FOR: ${index} IN RANGE [ 0 | 2 ] (5)
INFO - +--- END FOR: ${index} IN RANGE [ 0 | 2 ] (4)
INFO - +----- END TEST: Threading Test (3)
------------------------------------------------------
INFO - +-- END THREAD: TEST_THREAD_1 (5)
INFO - +- END THREAD: TEST_THREAD_2 (6)
======================================================
INFO - + END SUITE: Test.Threading (135)

The indentation of START and END is not aligned any more.

The file robotframework-6.1-py3.9.egg\robot\output\debugfile.py contains self._indent. Seems that self._indent does not know about threading. The variable only reacts on the start of something (self._indent += 1) and the end of something (self._indent -= 1).

And therefore also the start of a new thread (during the lifetime of another thread) increases the indentation:

INFO - +-- START THREAD: TEST_THREAD_1 [ ]
INFO - +--- START THREAD: TEST_THREAD_2 [ ]

But because of the parallelism of the threads I would not expect an increased indentation here.

The following log lines in the example above are a mix of the log output of both threads. This causes the indentation being unsynchronized completely especially at the end of log.

INFO - +--- END FOR: ${index} IN RANGE [ 0 | 2 ] (4)
INFO - +----- END TEST: Threading Test (3)
------------------------------------------------------
INFO - +-- END THREAD: TEST_THREAD_1 (5)
INFO - +- END THREAD: TEST_THREAD_2 (6)

Consequence: The indentation has to be thread save.

Addendum:

In opposite to https://github.com/test-fullautomation/robotframework/issues/77 the code above contains no coding error.

But even in this case the results are not stable. I execute the test repeatedly in a Windows console. Sometime the test result is PASS, sometimes the test crashes:

Threading Test                                                        | PASS |
------------------------------------------------------------------------------
Test.Threading :: Simple test suite                                   | PASS |
1 test, 1 passed, 0 failed, 0 unknown
Exception in thread TEST_THREAD_2:
==============================================================================
AttributeError: 'NoneType' object has no attribute 'status'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "D:\RobotFramework\python39\lib\threading.py", line 980, in _bootstrap_inner
Output:  D:\ROBFW\TestTestcases\RobotFramework\threading\logfiles\test.threading.xml
    self.run()
  File "D:\RobotFramework\python39\lib\threading.py", line 917, in run
    self._target(*self._args, **self._kwargs)
  File "D:\RobotFramework\python39\lib\site-packages\robotframework-6.1-py3.9.egg\robot\running\bodyrunner.py", line 548, in run_worker
    self._context.variables.end_thread()
  File "D:\RobotFramework\python39\lib\site-packages\robotframework-6.1-py3.9.egg\robot\running\statusreporter.py", line 67, in __exit__
    raise failure
robot.errors.HandlerExecutionFailed: AttributeError: 'NoneType' object has no attribute 'status'
Log:     D:\ROBFW\TestTestcases\RobotFramework\threading\logfiles\test.threading_log.html
Report:  D:\ROBFW\TestTestcases\RobotFramework\threading\logfiles\test.threading_report.html
------------------------------
RF returned ERRORLEVEL : 0
------------------------------

But also in this case the test result is PASS and the error level 0.

test-fullautomation / robotframework

Threading harms indentation in debug log file #78