1218006 - Intermittent log parsing error in debug mochitest-other jobs

Status: RESOLVED INCOMPLETE

(Release Engineering :: General, defect)

Description

[Nick Thomas [:nthomas] (UTC+12)]

This shows up as dead jobs in the command queue, and when you trace back to the build on the master (eg http://buildbot-master106.bb.releng.scl3.mozilla.com:8201/builders/Rev4%20MacOSX%20Snow%20Leopard%2010.6%20fx-team%20debug%20test%20mochitest-other/builds/665) you find

Traceback (most recent call last):
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/twisted/internet/defer.py", line 249, in addCallbacks
    self._runCallbacks()
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/twisted/internet/defer.py", line 441, in _runCallbacks
    self.result = callback(self.result, *args, **kw)
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/twisted/internet/defer.py", line 318, in callback
    self._startRunCallbacks(result)
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/twisted/internet/defer.py", line 424, in _startRunCallbacks
    self._runCallbacks()
--- <exception caught here> ---
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/twisted/internet/defer.py", line 441, in _runCallbacks
    self.result = callback(self.result, *args, **kw)
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/buildbot-0.8.2_hg_41f0fbee10f4_production_0.8-py2.7.egg/buildbot/process/buildstep.py", line 1074, in <lambda>

The tests had been running for 52 minutes at that point
    d.addCallback(lambda res: self.evaluateCommand(cmd)) # returns results
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/buildbotcustom/steps/base.py", line 14, in evaluateCommand
    lbs_status = obj.evaluateCommand(self, cmd)
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/buildbot-0.8.2_hg_41f0fbee10f4_production_0.8-py2.7.egg/buildbot/process/buildstep.py", line 1172, in evaluateCommand
    return self.log_eval_func(cmd, self.step_status)
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/buildbotcustom/process/factory.py", line 4677, in eval_func
    regex_status = regex_log_evaluator(cmd, step, global_errors)
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/buildbot-0.8.2_hg_41f0fbee10f4_production_0.8-py2.7.egg/buildbot/process/buildstep.py", line 1239, in regex_log_evaluator
    if err.search(l.getText()):
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/buildbot-0.8.2_hg_41f0fbee10f4_production_0.8-py2.7.egg/buildbot/status/builder.py", line 338, in getText
    return "".join(self.getChunks([STDOUT, STDERR], onlyText=True))
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/buildbot-0.8.2_hg_41f0fbee10f4_production_0.8-py2.7.egg/buildbot/status/builder.py", line 389, in _generateChunks
    p.dataReceived(data)
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/twisted/protocols/basic.py", line 99, in dataReceived
    self.doData()
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/twisted/protocols/basic.py", line 62, in doData
    self.stringReceived(self.__buffer)
  File "/builds/buildbot/tests1-macosx/lib/python2.7/site-packages/buildbot-0.8.2_hg_41f0fbee10f4_production_0.8-py2.7.egg/buildbot/status/builder.py", line 81, in stringReceived
    channel = int(line[0])
exceptions.ValueError: invalid literal for int() with base 10: ''

Comment 1

[Nick Thomas [:nthomas] (UTC+12)]

Another one, on linux this time:
http://buildbot-master05.build.mozilla.org:8201/builders/Ubuntu%20VM%2012.04%20try%20debug%20test%20mochitest-other/builds/2084

The log has a time jump and ends:
12:37:50     INFO -  [8591] WARNING: Trying to spellcheck, but checking seems to be disabled: 'mPendingSpellCheck', file /builds/slave/try-lx-d-000000000000000000000/build/src/extensions/spellcheck/src/mozInlineSpellChecker.cpp, line 908
12:37:50     INFO -  [8591] WARNING: Trying to spellcheck, but checking seems to be disabled: 'mPendingSpellCheck', file /builds/slave/try-lx-d-0000000000000000e to READY ...
09:06:01     INFO -  Setting pipeline to NULL ...
09:06:01     INFO -  Freeing pipeline ...
09:06:03     INFO -  pk12util: PKCS12 IMPORT SUCCESSFUL
09:06:04     INFO -  MochitestServer : launching [u'/builds/slave/test/build/tests/bin/xpcshell', '-g', '/builds/slave/test/build/application/firefox', '-v', '170', '-f', '/builds/slave/test/build/tests/bin/components/httpd.js', '-e', "const _PROFILE_PATH = '/tmp/tmpMKpGha.mozrunner'; const _SERVER_PORT = '8888'; const

Comment 2

[Phil Ringnalda (:philor)]

How does the time of these compare to the time when we had a reconfig that removed the mochitest-other job, then a backout and a reconfig which brought it back again?

Comment 3

[Nick Thomas [:nthomas] (UTC+12)]

Jobs ran on bm106 between
  Start	Fri Oct 23 10:01:12 2015
  End	Fri Oct 23 10:53:39 2015
  Elapsed	52 mins, 27 secs

Reconfigs at
2015-10-23 09:01:37-0700 [-] configuration update started
2015-10-23 09:06:03-0700 [-] configuration update complete
2015-10-23 10:00:27-0700 [-] configuration update started
2015-10-23 10:00:48-0700 [-] configuration update complete
2015-10-23 12:00:34-0700 [-] configuration update started
2015-10-23 12:00:45-0700 [-] configuration update complete

No obvious correlation there.