From 08aada5a10db91f710add97f16aa51e91c68ede4 Mon Sep 17 00:00:00 2001
From: David Jackson <58445547+daj-code@users.noreply.github.com>
Date: Sun, 21 Mar 2021 22:21:40 +0000
Subject: [PATCH 1/6] Adding logging of messages in threads to debugfile
protected via a multiprocessing Lock.
Tests still need fixing up here.
---
atest/robot/cli/runner/debugfile.robot | 32 +++++++++----------
.../test_libraries/ThreadLoggingLib.py | 26 +++++++++++----
src/robot/output/debugfile.py | 23 ++++++++++---
src/robot/output/librarylogger.py | 5 ++-
src/robot/output/logger.py | 19 +++++++++--
src/robot/output/output.py | 2 +-
6 files changed, 77 insertions(+), 30 deletions(-)
diff --git a/atest/robot/cli/runner/debugfile.robot b/atest/robot/cli/runner/debugfile.robot
index 984e3e8773b..ce8a0e01a52 100644
--- a/atest/robot/cli/runner/debugfile.robot
+++ b/atest/robot/cli/runner/debugfile.robot
@@ -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} - MainThread - INFO - +-- START KEYWORD: BuiltIn.Log ? Test 1 ?
+ ... ${TIMESTAMP} - MainThread - INFO - Test 1
+ ... ${TIMESTAMP} - MainThread - INFO - +-- 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} - MainThread - INFO - +-- START KEYWORD: BuiltIn.Log ? Logging with debug level | DEBUG ?
+ ... ${TIMESTAMP} - MainThread - DEBUG - Logging with debug level
+ ... ${TIMESTAMP} - MainThread - INFO - +-- END KEYWORD: BuiltIn.Log
Debug file should contain ${content} + END SUITE: Normal
Syslog Should Contain DebugFile: DeBug.TXT
${path} = Set Variable [:.\\w /\\\\~+-]*DeBug\\.TXT
@@ -31,13 +31,13 @@ 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} - MainThread - INFO - +-- START KEYWORD: BuiltIn.Log ? Test 1 ?
+ ... ${TIMESTAMP} - MainThread - INFO - Test 1
+ ... ${TIMESTAMP} - MainThread - INFO - +-- 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} - MainThread - INFO - +-- START KEYWORD: BuiltIn.Log ? Logging with debug level | DEBUG ?
+ ... ${TIMESTAMP} - MainThread - DEBUG - Logging with debug level
+ ... ${TIMESTAMP} - MainThread - INFO - +-- END KEYWORD: BuiltIn.Log
Debugfile timestamps are accurate
Run Tests --outputdir ${CLI OUTDIR} -b debug.txt -t LibraryAddsTimestampAsInteger
@@ -45,8 +45,8 @@ Debugfile timestamps are accurate
${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 - Current
+ ... ${tc.kws[0].msgs[0].timestamp} - MainThread - INFO - Known timestamp
+ ... ${tc.kws[0].msgs[1].timestamp} - MainThread - INFO - Current
Writing Non-ASCII To Debugfile
[Documentation] Tests also that '.txt' is appended if no extension given
@@ -54,8 +54,8 @@ Writing Non-ASCII To Debugfile
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} - MainThread - FAIL - Circle is 360°, Hyvää üötä, উৄ ৰ ৺ ট ৫ ৪ হ
+ Debugfile should contain ${content} ${TIMESTAMP} - MainThread - INFO - +- 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}
diff --git a/atest/testdata/test_libraries/ThreadLoggingLib.py b/atest/testdata/test_libraries/ThreadLoggingLib.py
index 58c1799353c..b03610bc329 100644
--- a/atest/testdata/test_libraries/ThreadLoggingLib.py
+++ b/atest/testdata/test_libraries/ThreadLoggingLib.py
@@ -7,17 +7,31 @@
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):
for i in range(100):
- logger.info(str(i))
+ if in_thread:
+ logger.warn(
+ ("In thread {0}: {1}\n" * 100).format(
+ threading.currentThread().getName(), 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):
for i in range(100):
- logging.info(str(i))
+ if in_thread:
+ logging.warning(
+ ("In thread {0}: {1}\n" * 100).format(
+ threading.currentThread().getName(), str(i)
+ )
+ )
+ else:
+ logging.info(str(i))
time.sleep(0.01)
diff --git a/src/robot/output/debugfile.py b/src/robot/output/debugfile.py
index 15797786d69..d12f4dc58c2 100644
--- a/src/robot/output/debugfile.py
+++ b/src/robot/output/debugfile.py
@@ -13,6 +13,8 @@
# 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
@@ -34,15 +36,19 @@ def DebugFile(path):
return _DebugFileWriter(outfile)
+_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')
@@ -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(), thread_name, level, 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
diff --git a/src/robot/output/librarylogger.py b/src/robot/output/librarylogger.py
index 919e4aac6bd..395712a9917 100644
--- a/src/robot/output/librarylogger.py
+++ b/src/robot/output/librarylogger.py
@@ -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.currentThread().getName() 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):
diff --git a/src/robot/output/logger.py b/src/robot/output/logger.py
index 2ee8a63ca91..11728b51327 100644
--- a/src/robot/output/logger.py
+++ b/src/robot/output/logger.py
@@ -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 = []
@@ -56,13 +57,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]
+ self._debugfile_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._debugfile_logger, self._console_logger, self._syslog,
+ self._xml_logger]
return [logger for logger in loggers + self._other_loggers if logger]
def __iter__(self):
@@ -121,6 +124,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)
@@ -151,6 +160,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):
diff --git a/src/robot/output/output.py b/src/robot/output/output.py
index 88a796e1e2b..f9fe8aa29d5 100644
--- a/src/robot/output/output.py
+++ b/src/robot/output/output.py
@@ -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)
From 08614b9b494115b419c0a05120ebbf5cac0613ea Mon Sep 17 00:00:00 2001
From: David Jackson <58445547+daj-code@users.noreply.github.com>
Date: Mon, 22 Mar 2021 23:11:31 +0000
Subject: [PATCH 2/6] Fixing an outputting bug due to the ordering of
loggers/listeners in logger.py, and updating documentation for this.
New test cases still to be added, but existing tests passing.
---
atest/robot/cli/runner/debugfile.robot | 32 +++++++++----------
.../CreatingTestLibraries.rst | 5 ++-
src/robot/output/debugfile.py | 2 +-
src/robot/output/logger.py | 9 +++---
4 files changed, 25 insertions(+), 23 deletions(-)
diff --git a/atest/robot/cli/runner/debugfile.robot b/atest/robot/cli/runner/debugfile.robot
index ce8a0e01a52..0f0c10835bf 100644
--- a/atest/robot/cli/runner/debugfile.robot
+++ b/atest/robot/cli/runner/debugfile.robot
@@ -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} - MainThread - INFO - +-- START KEYWORD: BuiltIn.Log ? Test 1 ?
- ... ${TIMESTAMP} - MainThread - INFO - Test 1
- ... ${TIMESTAMP} - MainThread - 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} - MainThread - INFO - +-- START KEYWORD: BuiltIn.Log ? Logging with debug level | DEBUG ?
- ... ${TIMESTAMP} - MainThread - DEBUG - Logging with debug level
- ... ${TIMESTAMP} - MainThread - 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
@@ -31,13 +31,13 @@ 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} - MainThread - INFO - +-- START KEYWORD: BuiltIn.Log ? Test 1 ?
- ... ${TIMESTAMP} - MainThread - INFO - Test 1
- ... ${TIMESTAMP} - MainThread - 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} - MainThread - INFO - +-- START KEYWORD: BuiltIn.Log ? Logging with debug level | DEBUG ?
- ... ${TIMESTAMP} - MainThread - DEBUG - Logging with debug level
- ... ${TIMESTAMP} - MainThread - 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
@@ -45,8 +45,8 @@ Debugfile timestamps are accurate
${tc} = Check Test Case LibraryAddsTimestampAsInteger
${content} = Get file ${CLI OUTDIR}/debug.txt
Debug file should contain ${content}
- ... ${tc.kws[0].msgs[0].timestamp} - MainThread - INFO - Known timestamp
- ... ${tc.kws[0].msgs[1].timestamp} - MainThread - INFO - Current
+ ... ${tc.kws[0].msgs[0].timestamp} - INFO - MainThread - Known timestamp
+ ... ${tc.kws[0].msgs[1].timestamp} - INFO - MainThread - Current
Writing Non-ASCII To Debugfile
[Documentation] Tests also that '.txt' is appended if no extension given
@@ -54,8 +54,8 @@ Writing Non-ASCII To Debugfile
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} - MainThread - FAIL - Circle is 360°, Hyvää üötä, উৄ ৰ ৺ ট ৫ ৪ হ
- Debugfile should contain ${content} ${TIMESTAMP} - MainThread - 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}
diff --git a/doc/userguide/src/ExtendingRobotFramework/CreatingTestLibraries.rst b/doc/userguide/src/ExtendingRobotFramework/CreatingTestLibraries.rst
index 3eefbf24c1c..a105714d6c3 100644
--- a/doc/userguide/src/ExtendingRobotFramework/CreatingTestLibraries.rst
+++ b/doc/userguide/src/ExtendingRobotFramework/CreatingTestLibraries.rst
@@ -2407,7 +2407,10 @@ 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.
There is also a `BackgroundLogger` in separate robotbackgroundlogger__ project,
with a similar API as the standard `robot.api.logger`. Normal logging
diff --git a/src/robot/output/debugfile.py b/src/robot/output/debugfile.py
index d12f4dc58c2..a06592198a9 100644
--- a/src/robot/output/debugfile.py
+++ b/src/robot/output/debugfile.py
@@ -109,7 +109,7 @@ def _write(self, text, separator=False, level='INFO', timestamp=None):
if not separator:
thread_name = threading.currentThread().getName()
text = '%s - %s - %s - %s' % (
- timestamp or get_timestamp(), thread_name, level, text
+ timestamp or get_timestamp(), level, thread_name, text
)
if self._lock:
self._lock.acquire()
diff --git a/src/robot/output/logger.py b/src/robot/output/logger.py
index 11728b51327..1726c8aa1af 100644
--- a/src/robot/output/logger.py
+++ b/src/robot/output/logger.py
@@ -56,16 +56,15 @@ def __init__(self, register_console_logger=True):
@property
def start_loggers(self):
- loggers = [self._console_logger, self._syslog, self._xml_logger,
- self._debugfile_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._debugfile_logger, 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):
From 48629fb8501a69ac87af7dca23e1c9411ab2c037 Mon Sep 17 00:00:00 2001
From: David Jackson <58445547+daj-code@users.noreply.github.com>
Date: Sat, 27 Mar 2021 22:42:02 +0000
Subject: [PATCH 3/6] Adding regression test for non-main threads logging being
written to debug file.
---
.../non_main_threads_logging.robot | 97 ++++++++++++++++++-
.../test_libraries/ThreadLoggingLib.py | 16 ++-
2 files changed, 107 insertions(+), 6 deletions(-)
diff --git a/atest/robot/test_libraries/non_main_threads_logging.robot b/atest/robot/test_libraries/non_main_threads_logging.robot
index f2cbd948f9e..9e005b76e2a 100644
--- a/atest/robot/test_libraries/non_main_threads_logging.robot
+++ b/atest/robot/test_libraries/non_main_threads_logging.robot
@@ -1,10 +1,41 @@
*** 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
+
+
*** 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}" test_libraries/non_main_threads_logging.robot
+ ${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}" test_libraries/non_main_threads_logging.robot
+ ${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
@@ -13,3 +44,65 @@ 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 the specified number of times (default 1).
+ [Arguments] ${content} @{lines} ${count}=None
+ Should Not Be Empty ${lines} Invalid usage!!
+ ${expected} = Catenate SEPARATOR=\n @{lines}
+ IF not ${count}
+ Should Match ${content} *${expected}*
+ ELSE
+ ${full_expected} = Set Variable ${expected}
+ FOR ${counter} IN RANGE ${count}
+ ${full_expected} = Catenate SEPARATOR=* ${full_expected} ${expected}
+ END
+ Should Match ${content} *${full_expected}*
+ END
+
+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
+
diff --git a/atest/testdata/test_libraries/ThreadLoggingLib.py b/atest/testdata/test_libraries/ThreadLoggingLib.py
index b03610bc329..628b1af356b 100644
--- a/atest/testdata/test_libraries/ThreadLoggingLib.py
+++ b/atest/testdata/test_libraries/ThreadLoggingLib.py
@@ -10,11 +10,15 @@ def log_using_robot_api_in_thread():
threading.Timer(0.1, log_using_robot_api, kwargs={"in_thread": True}).start()
def log_using_robot_api(in_thread=False):
+ thread_name = threading.currentThread().getName()
for i in range(100):
if in_thread:
logger.warn(
- ("In thread {0}: {1}\n" * 100).format(
- threading.currentThread().getName(), str(i)
+ ("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:
@@ -25,11 +29,15 @@ def log_using_logging_module_in_thread():
threading.Timer(0.1, log_using_logging_module, kwargs={"in_thread": True}).start()
def log_using_logging_module(in_thread=False):
+ thread_name = threading.currentThread().getName()
for i in range(100):
if in_thread:
logging.warning(
- ("In thread {0}: {1}\n" * 100).format(
- threading.currentThread().getName(), str(i)
+ ("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:
From 02070dea59113c4f3fd2899a1e0b4e3c9dcc6d6f Mon Sep 17 00:00:00 2001
From: David Jackson <58445547+daj-code@users.noreply.github.com>
Date: Sat, 27 Mar 2021 23:21:39 +0000
Subject: [PATCH 4/6] Minor improvements to try and match the CONTRIBUTING
guide's recommendations.
---
.../test_libraries/non_main_threads_logging.robot | 11 +++++++----
atest/testdata/test_libraries/ThreadLoggingLib.py | 8 ++------
.../ExtendingRobotFramework/CreatingTestLibraries.rst | 4 +++-
3 files changed, 12 insertions(+), 11 deletions(-)
diff --git a/atest/robot/test_libraries/non_main_threads_logging.robot b/atest/robot/test_libraries/non_main_threads_logging.robot
index 9e005b76e2a..0a37954d8bb 100644
--- a/atest/robot/test_libraries/non_main_threads_logging.robot
+++ b/atest/robot/test_libraries/non_main_threads_logging.robot
@@ -6,13 +6,14 @@ 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
[Documentation] Run the mainline test without debugfile enabled. Check
... that all logs from non-main threads are ignored.
- Run Tests -t "${MAINLINE SUITE TEST}" test_libraries/non_main_threads_logging.robot
+ Run Tests -t "${MAINLINE SUITE TEST}" ${SUITE FILE}
${tc} = Check Test Case ${MAINLINE SUITE TEST}
Check Log Messages In Main Testcase ${tc}
@@ -22,7 +23,7 @@ Log messages from non-main threads should be written to debug file
... 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}" test_libraries/non_main_threads_logging.robot
+ 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
@@ -83,10 +84,12 @@ Check Thread Debugfile Logs
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
+ ${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
+ ${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
diff --git a/atest/testdata/test_libraries/ThreadLoggingLib.py b/atest/testdata/test_libraries/ThreadLoggingLib.py
index 628b1af356b..e9243bb3d90 100644
--- a/atest/testdata/test_libraries/ThreadLoggingLib.py
+++ b/atest/testdata/test_libraries/ThreadLoggingLib.py
@@ -17,9 +17,7 @@ def log_using_robot_api(in_thread=False):
("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)
- )
+ ("Debugging in thread {0}: {1}\n" * 10).format(thread_name, str(i))
)
else:
logger.info(str(i))
@@ -36,9 +34,7 @@ def log_using_logging_module(in_thread=False):
("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)
- )
+ ("Debugging in thread {0}: {1}\n" * 10).format(thread_name, str(i))
)
else:
logging.info(str(i))
diff --git a/doc/userguide/src/ExtendingRobotFramework/CreatingTestLibraries.rst b/doc/userguide/src/ExtendingRobotFramework/CreatingTestLibraries.rst
index a105714d6c3..c841aac9e8f 100644
--- a/doc/userguide/src/ExtendingRobotFramework/CreatingTestLibraries.rst
+++ b/doc/userguide/src/ExtendingRobotFramework/CreatingTestLibraries.rst
@@ -2410,7 +2410,9 @@ Messages logged by non-main threads using the normal logging methods from
`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.
+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
From 3b02ce832caa418d85d974291fd95369d67e1f15 Mon Sep 17 00:00:00 2001
From: David Jackson <58445547+daj-code@users.noreply.github.com>
Date: Sat, 27 Mar 2021 23:36:40 +0000
Subject: [PATCH 5/6] Plumb through 'use_lock' parameter to 'DebugFile' class.
---
src/robot/output/debugfile.py | 4 ++--
1 file changed, 2 insertions(+), 2 deletions(-)
diff --git a/src/robot/output/debugfile.py b/src/robot/output/debugfile.py
index a06592198a9..4f24a24b76e 100644
--- a/src/robot/output/debugfile.py
+++ b/src/robot/output/debugfile.py
@@ -22,7 +22,7 @@
from .loggerhelper import IsLogged
-def DebugFile(path):
+def DebugFile(path, use_lock=True):
if not path:
LOGGER.info('No debug file')
return None
@@ -33,7 +33,7 @@ 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()
From a100c8c607d3668589b8b76f0b44e9a7f114030b Mon Sep 17 00:00:00 2001
From: David Jackson <58445547+daj-code@users.noreply.github.com>
Date: Sat, 27 Mar 2021 23:50:12 +0000
Subject: [PATCH 6/6] Remove unused functionality from test keyword to simply
the keyword.
---
.../test_libraries/non_main_threads_logging.robot | 14 +++-----------
1 file changed, 3 insertions(+), 11 deletions(-)
diff --git a/atest/robot/test_libraries/non_main_threads_logging.robot b/atest/robot/test_libraries/non_main_threads_logging.robot
index 0a37954d8bb..5721fc1ebe5 100644
--- a/atest/robot/test_libraries/non_main_threads_logging.robot
+++ b/atest/robot/test_libraries/non_main_threads_logging.robot
@@ -48,19 +48,11 @@ Check Log Messages In Main Testcase
Debugfile Should Contain
[Documentation] Check that the debugfile contents provided contain the
- ... specified lines the specified number of times (default 1).
- [Arguments] ${content} @{lines} ${count}=None
+ ... specified lines.
+ [Arguments] ${content} @{lines}
Should Not Be Empty ${lines} Invalid usage!!
${expected} = Catenate SEPARATOR=\n @{lines}
- IF not ${count}
- Should Match ${content} *${expected}*
- ELSE
- ${full_expected} = Set Variable ${expected}
- FOR ${counter} IN RANGE ${count}
- ${full_expected} = Catenate SEPARATOR=* ${full_expected} ${expected}
- END
- Should Match ${content} *${full_expected}*
- END
+ Should Match ${content} *${expected}*
Get Thread Logged String
[Documentation] Get the string logged in a thread as part of the main