Skip to content

Allow logs from non-main threads to be safely logged to the debug file #3917

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 9 commits into
base: master
Choose a base branch
from
Open

Allow logs from non-main threads to be safely logged to the debug file #3917

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
9 commits
Select commit Hold shift + click to select a range
08aada5
Adding logging of messages in threads to debugfile protected via a mu…
daj-code Mar 21, 2021
08614b9
Fixing an outputting bug due to the ordering of loggers/listeners in …
daj-code Mar 22, 2021
48629fb
Adding regression test for non-main threads logging being written to …
daj-code Mar 27, 2021
6e67bb0
Merge remote-tracking branch 'origin/master' into thread-logging-in-d…
daj-code Mar 27, 2021
02070de
Minor improvements to try and match the CONTRIBUTING guide's recommen…
daj-code Mar 27, 2021
3b02ce8
Plumb through 'use_lock' parameter to 'DebugFile' class.
daj-code Mar 27, 2021
a100c8c
Remove unused functionality from test keyword to simply the keyword.
daj-code Mar 27, 2021
817ef8d
Merge remote-tracking branch 'origin/master' into thread-logging-in-d…
daj-code Apr 2, 2021
1b968ea
Merge remote-tracking branch 'origin/master' into thread-logging-in-d…
daj-code Sep 19, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
32 changes: 16 additions & 16 deletions atest/robot/cli/runner/debugfile.robot
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,13 +13,13 @@ Debugfile
Debug file should contain ${content} + START SUITE: Normal
Debug file should contain ${content} +- START TEST: First One
Debug file should contain ${content}
... ${TIMESTAMP} - INFO - +-- START KEYWORD: BuiltIn.Log ? Test 1 ?
... ${TIMESTAMP} - INFO - Test 1
... ${TIMESTAMP} - INFO - +-- END KEYWORD: BuiltIn.Log
... ${TIMESTAMP} - INFO - MainThread - +-- START KEYWORD: BuiltIn.Log ? Test 1 ?
... ${TIMESTAMP} - INFO - MainThread - Test 1
... ${TIMESTAMP} - INFO - MainThread - +-- END KEYWORD: BuiltIn.Log
Debug file should contain ${content}
... ${TIMESTAMP} - INFO - +-- START KEYWORD: BuiltIn.Log ? Logging with debug level | DEBUG ?
... ${TIMESTAMP} - DEBUG - Logging with debug level
... ${TIMESTAMP} - INFO - +-- END KEYWORD: BuiltIn.Log
... ${TIMESTAMP} - INFO - MainThread - +-- START KEYWORD: BuiltIn.Log ? Logging with debug level | DEBUG ?
... ${TIMESTAMP} - DEBUG - MainThread - Logging with debug level
... ${TIMESTAMP} - INFO - MainThread - +-- END KEYWORD: BuiltIn.Log
Debug file should contain ${content} + END SUITE: Normal
Syslog Should Contain DebugFile: DeBug.TXT
${path} = Set Variable [:.\\w /\\\\~+-]*DeBug\\.TXT
Expand All @@ -31,31 +31,31 @@ Debugfile Log Level Should Always Be Debug
Run Tests Without Processing Output --outputdir ${CLI OUTDIR} -b debug.txt -o o.xml --loglevel WARN ${TESTFILE}
${content}= Get File ${CLI OUTDIR}/debug.txt
Debug file should contain ${content}
... ${TIMESTAMP} - INFO - +-- START KEYWORD: BuiltIn.Log ? Test 1 ?
... ${TIMESTAMP} - INFO - Test 1
... ${TIMESTAMP} - INFO - +-- END KEYWORD: BuiltIn.Log
... ${TIMESTAMP} - INFO - MainThread - +-- START KEYWORD: BuiltIn.Log ? Test 1 ?
... ${TIMESTAMP} - INFO - MainThread - Test 1
... ${TIMESTAMP} - INFO - MainThread - +-- END KEYWORD: BuiltIn.Log
Debug file should contain ${content}
... ${TIMESTAMP} - INFO - +-- START KEYWORD: BuiltIn.Log ? Logging with debug level | DEBUG ?
... ${TIMESTAMP} - DEBUG - Logging with debug level
... ${TIMESTAMP} - INFO - +-- END KEYWORD: BuiltIn.Log
... ${TIMESTAMP} - INFO - MainThread - +-- START KEYWORD: BuiltIn.Log ? Logging with debug level | DEBUG ?
... ${TIMESTAMP} - DEBUG - MainThread - Logging with debug level
... ${TIMESTAMP} - INFO - MainThread - +-- END KEYWORD: BuiltIn.Log

Debugfile timestamps are accurate
Run Tests --outputdir ${CLI OUTDIR} -b debug.txt -t LibraryAddsTimestampAsInteger
... test_libraries/timestamps_for_stdout_messages.robot
${tc} = Check Test Case LibraryAddsTimestampAsInteger
${content} = Get file ${CLI OUTDIR}/debug.txt
Debug file should contain ${content}
... ${tc.kws[0].msgs[0].timestamp} - INFO - Known timestamp
... ${tc.kws[0].msgs[1].timestamp} - INFO - <b>Current</b>
... ${tc.kws[0].msgs[0].timestamp} - INFO - MainThread - Known timestamp
... ${tc.kws[0].msgs[1].timestamp} - INFO - MainThread - <b>Current</b>

Writing Non-ASCII To Debugfile
[Documentation] Tests also that '.txt' is appended if no extension given
Run Tests Without Processing Output --outputdir ${CLI OUTDIR} --debugfile debug -o o.xml misc/non_ascii.robot
Directory Should Contain ${CLI OUTDIR} debug.txt o.xml
Stderr Should Be Empty
${content} = Get File ${CLI OUTDIR}/debug.txt
Debugfile should contain ${content} ${TIMESTAMP} - FAIL - Circle is 360°, Hyvää üötä, উৄ ৰ ৺ ট ৫ ৪ হ
Debugfile should contain ${content} ${TIMESTAMP} - INFO - +- START TEST: Ñöñ-ÄŚÇÏÏ Tëśt äņd Këywörd Nämës, Спасибо ? ?
Debugfile should contain ${content} ${TIMESTAMP} - FAIL - MainThread - Circle is 360°, Hyvää üötä, উৄ ৰ ৺ ট ৫ ৪ হ
Debugfile should contain ${content} ${TIMESTAMP} - INFO - MainThread - +- START TEST: Ñöñ-ÄŚÇÏÏ Tëśt äņd Këywörd Nämës, Спасибо ? ?

No Debugfile
Run Tests Without Processing Output --outputdir ${CLI OUTDIR} --debugfile NoNe -o o.xml ${TESTFILE}
Expand Down
92 changes: 90 additions & 2 deletions atest/robot/test_libraries/non_main_threads_logging.robot
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,10 +1,42 @@
*** Settings ***
Suite Setup Run Tests ${EMPTY} test_libraries/non_main_threads_logging.robot
Documentation Testing logging behaviour from non-main threads.
Resource atest_resource.robot


*** Variables ***
${TIMESTAMP} ???????? ??:??:??.???
${MAINLINE SUITE TEST} Log messages from non-main threads should be ignored
${SUITE FILE} test_libraries/non_main_threads_logging.robot


*** Test Cases ***
Log messages from non-main threads should be ignored
${tc} = Check Test Case ${TESTNAME}
[Documentation] Run the mainline test without debugfile enabled. Check
... that all logs from non-main threads are ignored.
Run Tests -t "${MAINLINE SUITE TEST}" ${SUITE FILE}
${tc} = Check Test Case ${MAINLINE SUITE TEST}
Check Log Messages In Main Testcase ${tc}

Log messages from non-main threads should be written to debug file
[Documentation] Run the mainline test with debugfile enabled. Check that
... all logs from non-main threads are ignored in all output
... except the debugfile, which should contain all the
... messages logged by all threads, without log lines having
... been written over each other.
Run Tests --debugfile debug.log -t "${MAINLINE SUITE TEST}" ${SUITE FILE}
${tc} = Check Test Case ${MAINLINE SUITE TEST}
Check Log Messages In Main Testcase ${tc}
${content} = Get File ${OUTDIR}/debug.log
Check Main Thread Debugfile Logs ${content}
Check Thread Debugfile Logs ${content}


*** Keywords ***
Check Log Messages In Main Testcase
[Documentation] Check that the messages logged in the main testcase for
... this suite (Log messages from non-main threads should be
... ignored) are as expected.
[Arguments] ${tc}
Should Be Empty ${tc.kws[0].msgs}
Should Be Empty ${tc.kws[1].msgs}
Check Log Message ${tc.kws[2].msgs[0]} 0
Expand All @@ -13,3 +45,59 @@ Log messages from non-main threads should be ignored
Check Log Message ${tc.kws[3].msgs[0]} 0
Check Log Message ${tc.kws[3].msgs[99]} 99
Length Should Be ${tc.kws[3].msgs} 100

Debugfile Should Contain
[Documentation] Check that the debugfile contents provided contain the
... specified lines.
[Arguments] ${content} @{lines}
Should Not Be Empty ${lines} Invalid usage!!
${expected} = Catenate SEPARATOR=\n @{lines}
Should Match ${content} *${expected}*

Get Thread Logged String
[Documentation] Get the string logged in a thread as part of the main
... testcase.
[Arguments] ${thread_id} ${base_log} ${count} ${level}
${log_string} = Set Variable ${TIMESTAMP} - ${level} - ${thread_id} - ${base_log}
FOR ${counter} IN RANGE 1 ${count}
${log_string} = Catenate SEPARATOR= ${log_string} ${base_log}
END
${log_string} = Catenate SEPARATOR= ${TIMESTAMP}
[Return] ${log_string}

Check Thread Debugfile Logs
[Documentation] Check that the messages logged by threads in the testcase
... to debugfile match the expected values.
...
... For each of the two threads, we should get all of the
... logged messages at the correct log level.
[Arguments] ${content}
FOR ${thread} IN Thread-1 Thread-2
FOR ${counter} IN RANGE 100
Log Checking expected line for thread ${thread} count ${counter}

${thread_logged_string} = Get Thread Logged String
... ${thread} In thread ${thread}: ${counter}\n 20 WARN
Debugfile Should Contain ${content} ${thread_logged_string}

${thread_logged_string} = Get Thread Logged String
... ${thread} Debugging in thread ${thread}: ${counter}\n 10 DEBUG
Debugfile Should Contain ${content} ${thread_logged_string}
END
END

Check Main Thread Debugfile Logs
[Documentation] Check that the messages logged by the main thread in the
... testcase to debugfile match the expected values.
...
... We should get each of the non-threaded messages. Since we
... get one of each of the numbers logged at INFO level for
... the two keywords, one using Robot logger and the other
... Python logging module, we check for at least two matches
... of each of the log lines.
[Arguments] ${content}
FOR ${counter} IN RANGE 100
${log_string} = Set Variable ${TIMESTAMP} - INFO - MainThread - ${counter}\n
Debugfile Should Contain ${content} ${log_string}*${log_string}
END

30 changes: 24 additions & 6 deletions atest/testdata/test_libraries/ThreadLoggingLib.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,17 +7,35 @@


def log_using_robot_api_in_thread():
threading.Timer(0.1, log_using_robot_api).start()
threading.Timer(0.1, log_using_robot_api, kwargs={"in_thread": True}).start()

def log_using_robot_api():
def log_using_robot_api(in_thread=False):
thread_name = threading.currentThread().getName()
for i in range(100):
logger.info(str(i))
if in_thread:
logger.warn(
("In thread {0}: {1}\n" * 20).format(thread_name, str(i))
)
logger.debug(
("Debugging in thread {0}: {1}\n" * 10).format(thread_name, str(i))
)
else:
logger.info(str(i))
time.sleep(0.01)

def log_using_logging_module_in_thread():
threading.Timer(0.1, log_using_logging_module).start()
threading.Timer(0.1, log_using_logging_module, kwargs={"in_thread": True}).start()

def log_using_logging_module():
def log_using_logging_module(in_thread=False):
thread_name = threading.currentThread().getName()
for i in range(100):
logging.info(str(i))
if in_thread:
logging.warning(
("In thread {0}: {1}\n" * 20).format(thread_name, str(i))
)
logging.debug(
("Debugging in thread {0}: {1}\n" * 10).format(thread_name, str(i))
)
else:
logging.info(str(i))
time.sleep(0.01)
7 changes: 6 additions & 1 deletion doc/userguide/src/ExtendingRobotFramework/CreatingTestLibraries.rst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2463,7 +2463,12 @@ background, there should be another keyword that checks the status of
the worker thread and reports gathered information accordingly.

Messages logged by non-main threads using the normal logging methods from
`programmatic logging APIs`_ are silently ignored.
`programmatic logging APIs`_ are silently ignored, except for in the
`debug file`_ when used. The debug file will contain messages logged by all
threads using the normal logging methods, but cannot guarantee that the logs
will always appear exactly in the order they were emitted by the threads. This
is new in Robot Framework 4.0.1 - prior to this logs from non-main threads were
not written to the debug file either.

There is also a `BackgroundLogger` in separate robotbackgroundlogger__ project,
with a similar API as the standard `robot.api.logger`. Normal logging
Expand Down
27 changes: 21 additions & 6 deletions src/robot/output/debugfile.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -13,14 +13,16 @@
# See the License for the specific language governing permissions and
# limitations under the License.

import threading
from multiprocessing import Lock
from robot.errors import DataError
from robot.utils import get_timestamp, file_writer, seq2str2

from .logger import LOGGER
from .loggerhelper import IsLogged


def DebugFile(path):
def DebugFile(path, use_lock=True):
if not path:
LOGGER.info('No debug file')
return None
Expand All @@ -31,18 +33,22 @@ def DebugFile(path):
return None
else:
LOGGER.info('Debug file: %s' % path)
return _DebugFileWriter(outfile)
return _DebugFileWriter(outfile, use_lock=use_lock)


_DEBUGFILE_LOCK = Lock()

class _DebugFileWriter:
_separators = {'SUITE': '=', 'TEST': '-', 'KEYWORD': '~'}
_lock = None

def __init__(self, outfile):
def __init__(self, outfile, use_lock=True):
self._indent = 0
self._kw_level = 0
self._separator_written_last = False
self._outfile = outfile
self._is_logged = IsLogged('DEBUG')
self._lock = _DEBUGFILE_LOCK if use_lock else None

def start_suite(self, suite):
self._separator('SUITE')
Expand Down Expand Up @@ -101,7 +107,16 @@ def _write(self, text, separator=False, level='INFO', timestamp=None):
if separator and self._separator_written_last:
return
if not separator:
text = '%s - %s - %s' % (timestamp or get_timestamp(), level, text)
self._outfile.write(text.rstrip() + '\n')
self._outfile.flush()
thread_name = threading.currentThread().getName()
text = '%s - %s - %s - %s' % (
timestamp or get_timestamp(), level, thread_name, text
)
if self._lock:
self._lock.acquire()
try:
self._outfile.write(text.rstrip() + '\n')
self._outfile.flush()
finally:
if self._lock:
self._lock.release()
self._separator_written_last = separator
5 changes: 4 additions & 1 deletion src/robot/output/librarylogger.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -40,8 +40,11 @@ def write(msg, level, html=False):
msg = unic(msg)
if level.upper() not in ('TRACE', 'DEBUG', 'INFO', 'HTML', 'WARN', 'ERROR'):
raise DataError("Invalid log level '%s'." % level)
message = Message(msg, level, html)
if threading.current_thread().name in LOGGING_THREADS:
LOGGER.log_message(Message(msg, level, html))
LOGGER.log_message(message)
else:
LOGGER.maybe_log_to_debugfile(message)


def trace(msg, html=False):
Expand Down
20 changes: 17 additions & 3 deletions src/robot/output/logger.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -39,6 +39,7 @@ def __init__(self, register_console_logger=True):
self._console_logger = None
self._syslog = None
self._xml_logger = None
self._debugfile_logger = None
self._listeners = None
self._library_listeners = None
self._other_loggers = []
Expand All @@ -55,14 +56,15 @@ def __init__(self, register_console_logger=True):

@property
def start_loggers(self):
loggers = [self._console_logger, self._syslog, self._xml_logger,
self._listeners, self._library_listeners]
loggers = [self._debugfile_logger, self._console_logger, self._syslog,
self._xml_logger, self._listeners, self._library_listeners]
return [logger for logger in self._other_loggers + loggers if logger]

@property
def end_loggers(self):
loggers = [self._listeners, self._library_listeners,
self._console_logger, self._syslog, self._xml_logger]
self._console_logger, self._syslog, self._xml_logger,
self._debugfile_logger]
return [logger for logger in loggers + self._other_loggers if logger]

def __iter__(self):
Expand Down Expand Up @@ -121,6 +123,12 @@ def register_listeners(self, listeners, library_listeners):
if listeners:
self._relay_cached_messages(listeners)

def register_debugfile_logger(self, logger):
self._debugfile_logger = self._wrap_and_relay(logger)

def unregister_debugfile_logger(self):
self._debugfile_logger = None

def register_logger(self, *loggers):
for logger in loggers:
logger = self._wrap_and_relay(logger)
Expand Down Expand Up @@ -151,6 +159,12 @@ def message(self, msg):
if self._error_listener:
self._error_listener()

def maybe_log_to_debugfile(self, msg):
"""Log messages to the debugfile logger (if enabled), not necessarily
from the MainThread."""
if self._debugfile_logger:
self._debugfile_logger.log_message(msg)

@property
@contextmanager
def cache_only(self):
Expand Down
2 changes: 1 addition & 1 deletion src/robot/output/output.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -36,7 +36,7 @@ def _register_loggers(self, debug_file):
LOGGER.register_xml_logger(self._xmllogger)
LOGGER.register_listeners(self.listeners or None, self.library_listeners)
if debug_file:
LOGGER.register_logger(debug_file)
LOGGER.register_debugfile_logger(debug_file)

def register_error_listener(self, listener):
LOGGER.register_error_listener(listener)
Expand Down