Skip to content
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.

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

\r in the log output causing autotest failure #106

Closed
ldoktor opened this issue Apr 28, 2014 · 3 comments
Closed

\r in the log output causing autotest failure #106

ldoktor opened this issue Apr 28, 2014 · 3 comments

Comments

@ldoktor
Copy link
Member

ldoktor commented Apr 28, 2014

Today this occurred while developing the sigproxy test. It's based on #65 code and in case (already existing test) parallel_stress execution fails, the output contains \r which is unlogable by autotest status_log_entry.

04/28 14:46:59 INFO |   subtest:0127|       RUNNING ----    ----    timestamp=1398689219    localtime=Apr 28 14:46:59   INFO: SubSubtest parallel_stress INFO: parallel_stress postprocess()
04/28 14:46:59 INFO |   subtest:0127|       RUNNING ----    ----    timestamp=1398689219    localtime=Apr 28 14:46:59   INFO: SubSubtest parallel_stress INFO: parallel_stress cleanup()
04/28 14:47:02 ERROR|      test:0414| Exception escaping from test:
Traceback (most recent call last):
  File "/home/medic/Work/Projekty/autotest/autotest-ldoktor/client/shared/test.py", line 411, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/home/medic/Work/Projekty/autotest/autotest-ldoktor/client/shared/test.py", line 830, in _call_test_function
    raise error.UnhandledTestFail(e)
UnhandledTestFail: Unhandled ValueError: Invalid character in message 'ERROR: parallel_stress failed to postprocess: DockerOutputError: Good: [\'crash_check_stdout\', \'usage_check_stdout\', \'crash_check_stderr\', \'usage_check_stderr\', \'error_check_stderr\']; Not Good: [\'error_check_stdout\']; Details: (error_check_stdout, Command exit 255 stdout "Received 1, ignoring...\r'
Traceback (most recent call last):
  File "/home/medic/Work/Projekty/autotest/autotest-ldoktor/client/shared/test.py", line 823, in _call_test_function
    return func(*args, **dargs)
  File "/home/medic/Work/Projekty/autotest/autotest-ldoktor/client/tests/docker/dockertest/subtest.py", line 132, in execute
    *args, **dargs)
  File "/home/medic/Work/Projekty/autotest/autotest-ldoktor/client/shared/test.py", line 291, in execute
    postprocess_profiled_run, args, dargs)
  File "/home/medic/Work/Projekty/autotest/autotest-ldoktor/client/shared/test.py", line 212, in _call_run_once
    self.run_once(*args, **dargs)
  File "/home/medic/Work/Projekty/autotest/autotest-ldoktor/client/tests/docker/dockertest/subtest.py", line 545, in run_once
    self.run_all_stages(name, self.new_subsubtest(name))
  File "/home/medic/Work/Projekty/autotest/autotest-ldoktor/client/tests/docker/dockertest/subtest.py", line 518, in run_all_stages
    self.try_all_stages(name, subsubtest)
  File "/home/medic/Work/Projekty/autotest/autotest-ldoktor/client/tests/docker/dockertest/subtest.py", line 493, in try_all_stages
    detail)
  File "/home/medic/Work/Projekty/autotest/autotest-ldoktor/client/tests/docker/dockertest/subtest.py", line 247, in logtraceback
    self.logerror(error_head)
  File "/home/medic/Work/Projekty/autotest/autotest-ldoktor/client/tests/docker/dockertest/subtest.py", line 233, in logerror
    return self._log('error', message, *args)
  File "/home/medic/Work/Projekty/autotest/autotest-ldoktor/client/tests/docker/dockertest/subtest.py", line 125, in _log
    sle = base_job.status_log_entry("RUNNING", None, None, message, {})
  File "/home/medic/Work/Projekty/autotest/autotest-ldoktor/client/shared/base_job.py", line 529, in __init__
    raise ValueError('Invalid character in message %r' % self.message)
ValueError: Invalid character in message 'ERROR: parallel_stress failed to postprocess: DockerOutputError: Good: [\'crash_check_stdout\', \'usage_check_stdout\', \'crash_check_stderr\', \'usage_check_stderr\', \'error_check_stderr\']; Not Good: [\'error_check_stdout\']; Details: (error_check_stdout, Command exit 255 stdout "Received 1, ignoring...\r'

04/28 14:47:02 INFO |   subtest:0127|       RUNNING ----    ----    timestamp=1398689222    localtime=Apr 28 14:47:02   INFO: cleanup()

I'll have to investigate it further to see whether autotest or docker needs to be modified. This issue is just to not forget about it.

@ldoktor ldoktor self-assigned this Apr 28, 2014
@cevich
Copy link
Member

cevich commented Apr 30, 2014

Yeah, I've run into this before. @ldoktor is this already fixed by cevich@fc5b547 currently merged already in #88

@ldoktor
Copy link
Member Author

ldoktor commented May 2, 2014

Hard to tell, it occurs randomly, so I can't verify it for sure...

@cevich
Copy link
Member

cevich commented May 5, 2014

Closing since 0.7.x is now using logging module directly, I think this problem is not possible. If you can reproduce it, all we need for a fix is to strip out any '\r' characters w/in the message-formatting methods..

@cevich cevich closed this as completed May 5, 2014
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

2 participants