[Buildbot] #2901: Finished time of a build step does not match the elapsedTime of the same step.

Buildbot trac trac at buildbot.net
Wed Sep 17 08:22:34 UTC 2014


#2901: Finished time of a build step does not match the elapsedTime of the same
step.
-------------------+--------------------
Reporter:  juj     |       Owner:
    Type:  defect  |      Status:  new
Priority:  major   |   Milestone:  0.9.0
 Version:  0.8.8   |  Resolution:
Keywords:          |
-------------------+--------------------

Comment (by juj):

 Looking at the logs I pasted in comment 4 and focusing at the step Tests-
 browser-firefox from run win-incoming 388, I see that the server log
 states it sends the command to start:

 {{{
 2014-09-17 05:36:00+0300 [-]
 ShellCommand.startCommand(cmd=<RemoteShellCommand
 '['run_emscripten_tests_browser_firefox.bat']'>)
 }}}

 the builder receives this and logs

 {{{
 2014-09-17 05:35:56+0300 [Broker,client] RunProcess._startCommand
 2014-09-17 05:35:56+0300 [Broker,client]
 'run_emscripten_tests_browser_firefox.bat'
 }}}

 then the builder runs the command, and 15 minutes later finishes, and
 sends

 {{{
 2014-09-17 05:51:28+0300 [-] command finished with signal None, exit code
 0, elapsedTime: 932.033000
 2014-09-17 05:51:28+0300 [-] SlaveBuilder.commandComplete
 <buildslave.commands.shell.SlaveShellCommand instance at 0x02ECB788>
 }}}

 however, the server does not log anything related to this, except two
 hours later(!) at

 {{{
 2014-09-17 07:51:42+0300 [Broker,87,85.23.62.181] <RemoteShellCommand
 '['run_emscripten_tests_browser_firefox.bat']'> rc=0
 2014-09-17 07:51:42+0300 [-] closing log <buildbot.status.logfile.LogFile
 instance at 0xd141bac>
 2014-09-17 07:51:42+0300 [-] addCompleteLog(passed (165))
 2014-09-17 07:51:42+0300 [-] addCompleteLog(failed (9))
 2014-09-17 07:51:42+0300 [-] addCompleteLog(skipped (8))
 2014-09-17 07:51:42+0300 [-] addCompleteLog(todos (1))
 2014-09-17 07:51:42+0300 [-] addCompleteLog(warnings (837))
 2014-09-17 07:51:42+0300 [-] releaseLocks(<RunEmscriptenTestsWithSummary
 object at 0xd172f6c>): []
 2014-09-17 07:51:42+0300 [-]  step 'Tests-browser-firefox' complete:
 success
 2014-09-17 07:51:42+0300 [-]  <Build win-incoming>: build finished
 2014-09-17 07:51:42+0300 [-]  setting expectations for next time
 2014-09-17 07:51:42+0300 [-] new expectations: 37795.9245304 seconds
 2014-09-17 07:51:42+0300 [-] releaseLocks(<BuildSlave 'win-slave'>): []
 2014-09-17 07:51:42+0300 [-] releaseLocks(<Build win-incoming>):
 [(<SlaveLock(slave_builds, 1)[win-slave] 3005554380>,
 <buildbot.locks.LockAccess instance at 0xc2b838c>)]
 }}}

 I think this is peeking at the issue: the server has received the task
 completion message, but for some reason, holds it up in a queue for two
 hours before processing it.

 This is possibly something Windows-specific, since I'm also running Linux
 and OSX build slaves on the same server that run the same steps, and they
 are working perfectly without problems.

--
Ticket URL: <http://trac.buildbot.net/ticket/2901#comment:6>
Buildbot <http://buildbot.net/>
Buildbot: build/test automation


More information about the bugs mailing list