Ticket #284 (closed defect: fixed)

Opened 8 months ago

Last modified 3 days ago

svn checkout (any mode) fails to remove build directory

Reported by: unwesen Assigned to:
Priority: major Milestone: undecided
Component: other Version: 0.7.7
Keywords: Cc: mpgritti, afri

Description

I've upgraded to Ubunty Hardy which upgrades buildbot from 0.7.5 to 0.7.6. Since then I'm seeing buildbot fail the svn step with the output below. It seems to fairly consistently fail at every second build.

The first build always succeeds, i.e. when no build directory exists. The second build fails at this step, although the build directory is empty afterwards. The third build succeeds again, and so on.

This is most notable with mode='export' et al., but mode='update' also clobbers the build directory in my case. Either way, it's mode='export' that I really want to use. 

starting svn operation
rm -rf /var/lib/buildbot/foo/localbot/foo-dist/build
 in dir /var/lib/buildbot/foo/localbot/foo-dist (timeout 1200 secs)
 watching logfiles {}
 argv: ['rm', '-rf', '/var/lib/buildbot/foo/localbot/foo-dist/build']
 environment:
  HOME=/var/lib/buildbot
  LOGNAME=buildbot
  MAIL=/var/mail/buildbot
  PATH=/usr/local/bin:/usr/bin:/bin:/usr/games
  PWD=/var/lib/buildbot
  SHELL=/bin/sh
  TERM=xterm-color
  USER=buildbot
 closing stdin
 using PTY: True
program finished with exit code -1

And the log file shows this: 

2008/05/20 11:43 +0200 [Broker,client]  startCommand:svn [id 17]
2008/05/20 11:43 +0200 [Broker,client] ShellCommand._startCommand
2008/05/20 11:43 +0200 [Broker,client]  rm -rf /var/lib/buildbot/foo/localbot/foo-dist/build
2008/05/20 11:43 +0200 [Broker,client]   in dir /var/lib/buildbot/foo/localbot/foo-dist (timeout 1200 secs)
2008/05/20 11:43 +0200 [Broker,client]   watching logfiles {}
2008/05/20 11:43 +0200 [Broker,client]   argv: ['rm', '-rf', '/var/lib/buildbot/foo/localbot/foo-dist/build']
2008/05/20 11:43 +0200 [Broker,client]  environment: {'TERM': 'xterm-color', 'SHELL': '/bin/sh', 'PWD': '/var/lib/buildbot', 'LOGNAME': 'bu>
2008/05/20 11:43 +0200 [Broker,client]   closing stdin
2008/05/20 11:43 +0200 [Broker,client]   using PTY: True
2008/05/20 11:43 +0200 [-] command finished with signal 1, exit code None
2008/05/20 11:43 +0200 [-] _checkAbandoned [Failure instance: Traceback: <class 'buildbot.slave.commands.AbandonChain'>: -1
>./usr/lib/python2.5/site-packages/buildbot/slave/commands.py:158:processEnded
>./usr/lib/python2.5/site-packages/buildbot/slave/commands.py:482:finished
>./usr/lib/python2.5/site-packages/twisted/internet/defer.py:239:callback
>./usr/lib/python2.5/site-packages/twisted/internet/defer.py:304:_startRunCallbacks
>.--- <exception caught here> ---
>./usr/lib/python2.5/site-packages/twisted/internet/defer.py:317:_runCallbacks
>./usr/lib/python2.5/site-packages/buildbot/slave/commands.py:707:_abandonOnFailure
>.]
2008/05/20 11:43 +0200 [-]  abandoning chain -1
2008/05/20 11:43 +0200 [-] SlaveBuilder.commandComplete <buildbot.slave.commands.SVN instance at 0xdf82d8>

I've not seen any change in buildbot's code surrounding this rm command between versions 0.7.5 and 0.7.6, so I've no idea what might have changed to make this happen. If I manually install Intrepid's 0.7.7 package (which again has no code change in that area that I can see), the same thing happens. Might this be a twisted problem?

Attachments

0001-Work-around-for-the-random-rm-deaths.patch (1.0 kB) - added by cmetcalf on 11/03/08 20:20:21.
Fix for this issue without --spew or global usepty=0 hacks

Change History

06/30/08 08:02:42 changed by anar

  • version changed from 0.7.6 to 0.7.7.

The same here with 0.7.7 :(

(follow-up: ↓ 3 ) 06/30/08 09:12:27 changed by dustin

Try posting to the mailing list to see if others have seen this behavior too. It's very strange.

(in reply to: ↑ 2 ) 06/30/08 09:23:41 changed by anar

Replying to dustin:

Try posting to the mailing list to see if others have seen this behavior too. It's very strange.

Thanx. I will.

BTW, I've just moved from 0.7.5 to .0.7.7. I haven't faced this issue with 0.7.5.

07/03/08 06:52:41 changed by anar

I am not able to reproduce this issue any more. After the first night build everything works as expected. Before I was able to reproduce it by executing "force build". A really strange case.

07/30/08 03:29:38 changed by mpgritti

Seeing the same issue with 0.7.7 and clobber.

07/30/08 03:29:53 changed by mpgritti

  • cc set to mpgritti.

08/04/08 05:40:02 changed by afri

  • cc changed from mpgritti to mpgritti, afri.

(follow-up: ↓ 10 ) 08/11/08 02:56:24 changed by dagvl

I am seeing this same issue on one specific buildserver. From the log 

2008/08/11 11:31 +0200 [Broker,client] <SlaveBuilder 'mock_sequencer-linux-full' at 138867660>.startBuild
2008/08/11 11:31 +0200 [Broker,client]  startCommand:svn [id 19]
2008/08/11 11:31 +0200 [Broker,client] ShellCommand._startCommand
2008/08/11 11:31 +0200 [Broker,client]  rm -rf /home/buildslave/vizrt-linux-build/mock_sequencer-linux-full/build
2008/08/11 11:31 +0200 [Broker,client]   in dir /home/buildslave/vizrt-linux-build/mock_sequencer-linux-full (timeout 1200 secs)
2008/08/11 11:31 +0200 [Broker,client]   watching logfiles {}
2008/08/11 11:31 +0200 [Broker,client]   argv: ['rm', '-rf', '/home/buildslave/vizrt-linux-build/mock_sequencer-linux-full/build']
2008/08/11 11:31 +0200 [Broker,client]  environment: {'LANG': 'en_US.UTF-8', 'TERM': 'xterm', 'SHELL': '/bin/sh', 'LANGUAGE': 'en_SE:en', 'MAIL': '/var/mail/buildslave', 'PWD': '/home/buildslave', 'LOGNAME': 'buildslave', 'USER': 'buildslave', 'HOME': '/home/buildslave', 'PATH': '/usr/local/bin:/usr/bin:/bin:/usr/games'}
2008/08/11 11:31 +0200 [Broker,client]   closing stdin
2008/08/11 11:31 +0200 [Broker,client]   using PTY: True
2008/08/11 11:31 +0200 [-] command finished with signal 1, exit code None
2008/08/11 11:31 +0200 [-] _checkAbandoned [Failure instance: Traceback: <class 'buildbot.slave.commands.AbandonChain'>: -1
        /usr/local/lib/python2.5/site-packages/buildbot-0.7.8-py2.5.egg/buildbot/slave/commands.py:158:processEnded
        /usr/local/lib/python2.5/site-packages/buildbot-0.7.8-py2.5.egg/buildbot/slave/commands.py:482:finished
        /usr/local/lib/python2.5/site-packages/twisted/internet/defer.py:239:callback
        /usr/local/lib/python2.5/site-packages/twisted/internet/defer.py:304:_startRunCallbacks
        --- <exception caught here> ---
        /usr/local/lib/python2.5/site-packages/twisted/internet/defer.py:317:_runCallbacks
        /usr/local/lib/python2.5/site-packages/buildbot-0.7.8-py2.5.egg/buildbot/slave/commands.py:707:_abandonOnFailure
        ]
2008/08/11 11:31 +0200 [-]  abandoning chain -1
2008/08/11 11:31 +0200 [-] SlaveBuilder.commandComplete <buildbot.slave.commands.SVN instance at 0x8484e2c>

It's failing consistently every other build, but only when using mode='clobber' on the SVN checkout.

Versions: 

$ buildbot --version
Buildbot version: 0.7.8
Twisted version: 8.1.0

08/11/08 04:03:57 changed by dagvl

Adding usepty=0 (as mentioned in #255) seems to have fixed this problem for me at least.

(in reply to: ↑ 8 ) 10/29/08 16:13:18 changed by cmetcalf

It's failing consistently every other build, but only when using mode='clobber' on the SVN checkout. Versions: {{{ $ buildbot --version Buildbot version: 0.7.8 Twisted version: 8.1.0 }}}

Same exact behavior with git repositories.

Buildbot version: 0.7.9 Twisted version: 8.1.0

11/02/08 03:46:31 changed by unwesen

Thanks dagvl! Setting usepty=0 in the slave's buildbot.tac solves the issue for me as well.

11/03/08 20:20:21 changed by cmetcalf

  • attachment 0001-Work-around-for-the-random-rm-deaths.patch added.

Fix for this issue without --spew or global usepty=0 hacks

11/17/08 07:56:44 changed by mue

I have the same issue and spend some time tracking down the problem. Here is what I discovered:

  • buildbot use a twisted function for spawning a process
  • this twisted function use the command start-stop-daemon, if available
  • start-stop-daemon then executes the given command (in this case rm -rf xxx)

now comes the clue:

  • start-stop-daemon returns the following: 
    $ start-stop-daemon --help
...snip...
Exit status:  0 = done      1 = nothing done (=> 0 if --oknodo)
              3 = trouble   2 = with --retry, processes wouldn't die
(from start-stop-daemon --help)

-> if there is no directory from a previous build, then rm has to do nothing
-> start-stop-daemon returns a 1
-> buildbot interpret this as a fail

This is a very tricky problem, I have other machines without start-stop-daemon and everything works fine. I have no clue how to fix this in twisted/buildbot, so I will try the patch above.

env: 

$ buildbot --version
Buildbot version: 0.7.9
Twisted version: 8.1.0

$ start-stop-daemon --version
start-stop-daemon 1.13.11+gentoo

11/17/08 07:59:38 changed by unwesen

Well, that's very clearly a twisted bug then. They should guarantee consistent return values.

(follow-up: ↓ 15 ) 11/17/08 08:11:40 changed by unwesen

Hmm, what twisted function would that be? I can't find mention of start-stop-daemon in the twisted sources, apart from in twisted/scripts/tap2deb.py , which doesn't look like it's involved in spawning processes.

(in reply to: ↑ 14 ) 11/18/08 05:43:05 changed by mue

Replying to unwesen:

Hmm, what twisted function would that be? I can't find mention of start-stop-daemon in the twisted sources, apart from in twisted/scripts/tap2deb.py , which doesn't look like it's involved in spawning processes.

I don't know much about twisted. I just discovered start-stop-daemon in my logs. I can provide 2 logs, one from a machine with start-stop-daemon installed and one without:

The one with start-stop-daemon: 

starting svn operation
rm -rf /var/lib/buildslave_et/MainApp/build
 in dir /var/lib/buildslave_et/MainApp (timeout 1200 secs)
 watching logfiles {}
 argv: ['rm', '-rf', '/var/lib/buildslave_et/MainApp/build']
 environment:
  BOOTLEVEL=boot
  CONSOLETYPE=pty
  DEFAULTLEVEL=default
  HOME=/var/lib/buildslave_et
  PATH=/bin:/sbin:/usr/bin:/usr/sbin:/usr/local/sbin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/opt/bin:/usr/i486-pc-linux-gnu/gcc-bin/4.1.2:/usr/i686-pc-linux-gnu/gcc-bin/4.1.2
  PWD=/root
  SHELL=/bin/bash
  SHLVL=1
  SOFTLEVEL=default
  SVCNAME=buildslave_et
  TERM=xterm
  USER=root
  _=/sbin/start-stop-daemon
 closing stdin
 using PTY: True
elapsedTime=1.684109
program finished with exit code -1

Take note of this line: 

  _=/sbin/start-stop-daemon

The one without start-stop-daemon: 

starting svn operation
rm -rf /home/buildslave/MainApp/build
 in dir /home/buildslave/MainApp (timeout 1200 secs)
 watching logfiles {}
 argv: ['rm', '-rf', '/home/buildslave/MainApp/build']
 environment:
  G_BROKEN_FILENAMES=1
  HISTSIZE=1000
  HOME=/root
  HOSTNAME=ppc
  INPUTRC=/etc/inputrc
  LESSOPEN=|/usr/bin/lesspipe.sh %s
  LOGNAME=root
  LS_COLORS=no=00:fi=00:di=00;33;40:ln=00;36:pi=40;34:so=00;35:bd=40;33;01:cd=40;33;01:or=01;05;37;41:mi=01;05;37;41:ex=00;32:*.cmd=00;32:*.exe=00;32:*.com=00;32:*.btm=00;32:*.bat=00;32:*.sh=00;32:*.csh=00;32:*.tar=00;31:*.tgz=00;31:*.arj=00;31:*.taz=00;31:*.lzh=00;31:*.zip=00;31:*.z=00;31:*.Z=00;31:*.gz=00;31:*.bz2=00;31:*.bz=00;31:*.tz=00;31:*.rpm=00;31:*.cpio=00;31:*.jpg=00;35:*.gif=00;35:*.bmp=00;35:*.xbm=00;35:*.xpm=00;35:*.png=00;35:*.tif=00;35:
  MAIL=/var/spool/mail/root
  MAKEFLAGS=
  MAKELEVEL=1
  MFLAGS=
  OLDPWD=/home
  PATH=/usr/kerberos/sbin:/usr/kerberos/bin:/opt/bin:/usr/local/sbin:/usr/local/bin:/sbin:/bin:/usr/sbin:/usr/bin:/usr/X11R6/bin
  PWD=/home/buildslave
  REMOTEHOST=192.168.111.19
  SHELL=/bin/sh
  SHLVL=1
  TERM=xterm
  USER=root
  _=/usr/bin/make
 closing stdin
 using PTY: True
elapsedTime=43.058613

Take note of this line: 

  _=/usr/bin/make

These are different machines with different environments, the first is a x86 with Gentoo Linux and the second is an embedded system with a MPC5200. But this shouldn't be an problem.

I hope to help on this issue. If more informations are needed, just ask.

(follow-up: ↓ 17 ) 11/18/08 06:36:33 changed by unwesen

Hmm. I for one don't have _ in my environment at all, whether I set usepty or not. I'm not sure that's really to do with the problem, therefore.

Here's what bash's man page tells me: 

_      At shell startup, set to the absolute pathname used to invoke the shell or shell
       script being executed as passed in the environment or argument list.
       Subsequently, expands  to  the last argument to the previous command, after
       expansion.  Also set to the full pathname used to invoke each command executed
       and placed in the environment exported to that command.  When checking mail,
       this parameter holds the name of the mail file currently being checked.

As far as I am concerned, launching a process shouldn't require invoking a shell. If there's no shell to be invoked, I'm not sure what _ does in the environment.

I've dug into the Twisted source a little, and they seem to use os.fork()/os.execvpe() to spawn processes. The latter should not launch a shell.

I'm assuming that the _ you see in your environment is inherited from the shell that starts your buildbot instance. Is it possible that in one case it's started via start-stop-daemon, and in the other via make?

I may be very wrong in this ;) It's just my current thinking.

(in reply to: ↑ 16 ) 11/18/08 08:47:10 changed by mue

Replying to unwesen:

I'm assuming that the _ you see in your environment is inherited from the shell that starts your buildbot instance. Is it possible that in one case it's started via start-stop-daemon, and in the other via make? I may be very wrong in this ;) It's just my current thinking.

Ok, that point goes to you ;) You are right, in one case it's started via start-stop-daemon and in the other via make. It looked so good...

Well, back to the ticket. The problem remains, I can reproduce the failed svn-step very good. Every second time the build runs it fails. I've made some tests, and it fails if there is no directory to remove.

(follow-up: ↓ 19 ) 01/05/09 09:33:48 changed by daniel@zuster.org

I have been having this problem as well but haven't investigated yet.

It looks from the log file that the child process is getting a SIGHUP: "2008/05/20 11:43 +0200 [-] command finished with signal 1, exit code None" which would explain how usepty=0 could work around the issue.

(in reply to: ↑ 18 ) 01/05/09 09:58:29 changed by cmetcalf

Replying to daniel@zuster.org:

I have been having this problem as well but haven't investigated yet. It looks from the log file that the child process is getting a SIGHUP: "2008/05/20 11:43 +0200 [-] command finished with signal 1, exit code None" which would explain how usepty=0 could work around the issue.

This should be fixed in Dustin's branch on github.

01/06/09 10:17:41 changed by dustin

  • status changed from new to closed.
  • resolution set to fixed.

http://github.com/djmitche/buildbot/commit/97240c6cdd527f5414e98336274e0652368cce3b Author: Chad Metcalf <cmetcalf@archrock.com> Date: Tue Dec 30 14:56:37 2008 -0800

(addresses: #255) rm commands can't use usePTY

Just fixes one instance of the problem as discussed in http://buildbot.net/trac/ticket/255