Realtime logging not available when [timeout] is used in a test case

[gajendraks]

Steps to reproduce:

• Include [Timeout] in the test case
• Execute the robot suite

*** Settings ***
Library     lib.py

*** Test Cases ***
Test
    [Timeout]    20 sec
    Keyword

Observed

• The logs are not getting written into the the console output or the debugfile until keyword ends.

Expected

• The logs should appear in console and debugfile in realtime.

Note: I see the realtime logging happening to console output and debugfile in the v3.0.4. But not in v3.2.1

[pekkaklarck]

This is most likely caused by the fix to #2839 in RF 3.1. Could you also show what your Keyword in lib.py does?

[gajendraks]

Note: I changed timeout to 20sec in the above comment and the Keyword in lib.py is defined as below

def keyword():
    logging.debug('before')
    time.sleep(5)
    logging.debug('after')

the logging happens in realtime when [Timeout] is removed

[smahantshetti]

i am facing the same exact issue.

$ robot --version
Robot Framework 5.0.1 (Python 3.6.8 on linux)

if i remove/comment out the timeout in test case, then logging is Realtime in logfile and everything works fine

    [Teardown]
#    [Timeout]    12h

also, same issue if i use a default timeout ex:

*** Settings ***
Test Timeout    3h

is there a workaround or a fix in queue for this please ? its very important especially when a keyword is stuck and i cannot tell if its really stuck or processing some statement in the code. i can only know after the keyword is complete or i abruptly cancel it.

[pekkaklarck]

Logged messages are cached , not written directly to disk, when using timeouts to avoid corrupting output.xml if a timeout expires exactly when a message is written. See #2839 for details about that very severe problem.

To avoid caching, we needed to come up with some other way to protect logger from timeouts. Until that, a workaround is not using timeouts (they should in general be used only when absolutely necessary) or logging to some external file or to sys.__stdout__ to see messages in realtime.

[smahantshetti]

Thanks @pekkaklarck we currently using built-in robot logger to log all debug messages (-b DEBUG.log -d logs) and logger statements are all over in almost all of the libraries in our code. so i think it may not be feasible to replace all that with some other way of logging.

from robot.api import logger
logger.debug()
logger.info()

i think one way would be to downgrade our robot to 3.0 version where this worked fine (And we had not issues with corrupt xml) until there is a fix.