[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