Commit f9ad242a authored by Jérome Perrin's avatar Jérome Perrin

grid: fix "log buildout output in realtime"

this fixes 86ce8b8e which had an error
the current_output variable was not reset when the current output ended
in \n.

As a result, logged output was sometimes containing some parts of the
program output twice. We could even catch it in unit test, when running
the test multiple times. It also happened on test node with
https://erp5js.nexedi.net/#/test_result_module/20210826-1706D7F50/10

The is trivial, we reset the current output also in this case. The test
suite is extended a bit, with added tests and test adjustments made during
the debugging. With test_exec_large_output_multiline the problem triggers
almost every time.
parent 1b95f815
...@@ -104,6 +104,7 @@ def logAndAccumulateOutput(process_stdout, buffer, logger): ...@@ -104,6 +104,7 @@ def logAndAccumulateOutput(process_stdout, buffer, logger):
for current_output_line in current_output.splitlines(True): for current_output_line in current_output.splitlines(True):
if current_output_line.endswith('\n'): if current_output_line.endswith('\n'):
logger.info(current_output_line.rstrip('\n')) logger.info(current_output_line.rstrip('\n'))
current_output = ''
else: else:
current_output = current_output_line current_output = current_output_line
......
...@@ -61,7 +61,7 @@ class SlapPopenTestCase(unittest.TestCase): ...@@ -61,7 +61,7 @@ class SlapPopenTestCase(unittest.TestCase):
self.assertEqual('hello\n', program.output) self.assertEqual('hello\n', program.output)
# output is also logged "live" # output is also logged "live"
logger.info.assert_called_with('hello') logger.info.assert_called_once_with('hello')
def test_exec_multiline(self): def test_exec_multiline(self):
self.script.write(textwrap.dedent('''\ self.script.write(textwrap.dedent('''\
...@@ -82,6 +82,25 @@ class SlapPopenTestCase(unittest.TestCase): ...@@ -82,6 +82,25 @@ class SlapPopenTestCase(unittest.TestCase):
self.assertEqual('hello\nworld\n', program.output) self.assertEqual('hello\nworld\n', program.output)
self.assertEqual(logger.info.call_args_list, [mock.call('hello'), mock.call('world')]) self.assertEqual(logger.info.call_args_list, [mock.call('hello'), mock.call('world')])
def test_exec_large_output_multiline(self):
output_line_list = [str(x) for x in range(100)]
self.script.write((
'\n'.join(
['#!/bin/sh']
+ ['echo ' + x for x in output_line_list]
)).encode())
self.script.close()
logger = mock.MagicMock()
program = slapos.grid.utils.SlapPopen(
self.script.name,
logger=logger)
self.assertEqual("\n".join(output_line_list) + '\n', program.output)
self.assertEqual(
logger.info.call_args_list,
[mock.call(x) for x in output_line_list])
def test_exec_non_ascii(self): def test_exec_non_ascii(self):
self.script.write(b'#!/bin/sh\necho h\xc3\xa9h\xc3\xa9') self.script.write(b'#!/bin/sh\necho h\xc3\xa9h\xc3\xa9')
self.script.close() self.script.close()
...@@ -92,7 +111,20 @@ class SlapPopenTestCase(unittest.TestCase): ...@@ -92,7 +111,20 @@ class SlapPopenTestCase(unittest.TestCase):
logger=logger) logger=logger)
self.assertEqual('héhé\n', program.output) self.assertEqual('héhé\n', program.output)
logger.info.assert_called_with('héhé') logger.info.assert_called_once_with('héhé')
def test_exec_large_output(self):
large_output = 'x' * 10000
self.script.write(('#!/bin/sh\necho %s' % large_output).encode())
self.script.close()
logger = mock.MagicMock()
program = slapos.grid.utils.SlapPopen(
self.script.name,
logger=logger)
self.assertEqual(large_output + '\n', program.output)
logger.info.assert_called_once_with(large_output)
def test_debug(self): def test_debug(self):
"""Test debug=True, which keeps interactive. """Test debug=True, which keeps interactive.
......
Markdown is supported
0%
or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment