plague: Job waited too long for repo to unlock. Killing it...

[Michael Schwendt]

If in a failed job.log you see the message

    Job waited too long for repo to unlock. Killing it...

please notify me.

It's a problem in the plague server code that results in a denial of
service for subsequent build jobs. I have a traceback from Dec 28th, but
in the context of the source code it doesn't make sense yet (because a few
lines earlier the code ensures that the files to be copied exist and are
readable). Buildsys runs a slightly modified version that adds a bit more
debug output in this area.

[...]

37683 (grads/ppc): Build result files - [ 'state.log',
'grads-1.9b4-21.el5.src.rpm', 'grads-debuginfo-1.9b4-21.el5.ppc.rpm',
'grads-1.9b4-21.el5.ppc.rpm', 'root.log', 'build.log',
'job.log' ]
37683 (grads/x86_64): Build result files - [ 'root.log', 'build.log',
'grads-debuginfo-1.9b4-21.el5.x86_64.rpm',
'grads-1.9b4-21.el5.x86_64.rpm', 'grads-1.9b4-21.el5.src.rpm',
'state.log', 'job.log' ]
37683 (grads/i386): Build result files - [ 'build.log', 'state.log',
'grads-1.9b4-21.el5.i386.rpm', 'job.log', 'root.log',
'grads-debuginfo-1.9b4-21.el5.i386.rpm', 'grads-1.9b4-21.el5.src.rpm' ]
Repo 'fedora-5-epel': updating repository metadata...
Exception in thread Repo: fedora-5-epel:
Traceback (most recent call last):
  File "/usr/lib64/python2.3/threading.py", line 436, in __bootstrap
    self.run()
  File "/usr/share/plague/server/Repo.py", line 233, in run
    self._update_repo()
  File "/usr/share/plague/server/Repo.py", line 137, in _update_repo
    shutil.copy(src, file_in_dst)
  File "/usr/lib64/python2.3/shutil.py", line 72, in copy
    copymode(src, dst)
  File "/usr/lib64/python2.3/shutil.py", line 49, in copymode
    st = os.stat(src)
OSError: [Errno 2] No such file or directory:
'/srv/rpmbuild/server_work/fedora-5-epel/37683-grads-1.9b4-21.el5/x86_64/grads-1.9b4-21.el5.x86_64.rpm'
37683 (grads): Job finished.

[Jonathan Dieter]

On Sun, 2007-12-30 at 17:54 +0100, Michael Schwendt wrote:
>  If in a failed job.log you see the message
>  
>      Job waited too long for repo to unlock. Killing it...
>  
>  please notify me.
>   
I ran into this with deltarpm for EL-5, job 37699.

Jonathan

[Michael Schwendt]

On Sun, 30 Dec 2007 20:14:36 +0200, Jonathan Dieter wrote:

>  On Sun, 2007-12-30 at 17:54 +0100, Michael Schwendt wrote:
>  > If in a failed job.log you see the message
>  > 
>  >     Job waited too long for repo to unlock. Killing it...
>  > 
>  > please notify me.
>  > 
>  
>  I ran into this with deltarpm for EL-5, job 37699. 
Yes, that's what the DoS symptoms look like: a short job.log and no other
results. Every job after 37683 did not even start, waiting forever for a
thread lock to be unlocked.

[Dan Williams]

On Sun, 2007-12-30 at 17:54 +0100, Michael Schwendt wrote:
>  If in a failed job.log you see the message
>  
>      Job waited too long for repo to unlock. Killing it...
>  
>  please notify me.
>  
>  It's a problem in the plague server code that results in a denial of
>  service for subsequent build jobs. I have a traceback from Dec 28th, but
>  in the context of the source code it doesn't make sense yet (because a few
>  lines earlier the code ensures that the files to be copied exist and are
>  readable). Buildsys runs a slightly modified version that adds a bit more
>  debug output in this area. 
Maybe just trap the exception, print it out, and continue?  That way at
least the server doesn't fall over, it just fails to copy one item.  It
might also help debugging to see if only specific files can't be
copied...

Dan

>  [...]
>  
>  37683 (grads/ppc): Build result files - [ 'state.log',
> 'grads-1.9b4-21.el5.src.rpm', 'grads-debuginfo-1.9b4-21.el5.ppc.rpm',
> 'grads-1.9b4-21.el5.ppc.rpm', 'root.log', 'build.log',
> 'job.log' ]
>  37683 (grads/x86_64): Build result files - [ 'root.log', 'build.log',
> 'grads-debuginfo-1.9b4-21.el5.x86_64.rpm',
> 'grads-1.9b4-21.el5.x86_64.rpm', 'grads-1.9b4-21.el5.src.rpm',
> 'state.log', 'job.log' ]
>  37683 (grads/i386): Build result files - [ 'build.log', 'state.log',
> 'grads-1.9b4-21.el5.i386.rpm', 'job.log', 'root.log',
> 'grads-debuginfo-1.9b4-21.el5.i386.rpm', 'grads-1.9b4-21.el5.src.rpm' ]
>  Repo 'fedora-5-epel': updating repository metadata...
>  Exception in thread Repo: fedora-5-epel:
>  Traceback (most recent call last):
>    File "/usr/lib64/python2.3/threading.py", line 436, in __bootstrap
>      self.run()
>    File "/usr/share/plague/server/Repo.py", line 233, in run
>      self._update_repo()
>    File "/usr/share/plague/server/Repo.py", line 137, in _update_repo
>      shutil.copy(src, file_in_dst)
>    File "/usr/lib64/python2.3/shutil.py", line 72, in copy
>      copymode(src, dst)
>    File "/usr/lib64/python2.3/shutil.py", line 49, in copymode
>      st = os.stat(src)
>  OSError: [Errno 2] No such file or directory:
> '/srv/rpmbuild/server_work/fedora-5-epel/37683-grads-1.9b4-21.el5/x86_64/grads-1.9b4-21.el5.x86_64.rpm'
>  37683 (grads): Job finished.
>  
>  --
>  Fedora-buildsys-list mailing list
>  Fedora-buildsys-list(a)redhat.com
>  https://www.redhat.com/mailman/listinfo/fedora-buildsys-list

[Michael Schwendt]

On Mon, 31 Dec 2007 11:00:12 -0500, Dan Williams wrote:

>  On Sun, 2007-12-30 at 17:54 +0100, Michael Schwendt wrote:
>  > If in a failed job.log you see the message
>  > 
>  >     Job waited too long for repo to unlock. Killing it...
>  > 
>  > please notify me.
>  > 
>  > It's a problem in the plague server code that results in a denial of
>  > service for subsequent build jobs. I have a traceback from Dec 28th, but
>  > in the context of the source code it doesn't make sense yet (because a few
>  > lines earlier the code ensures that the files to be copied exist and are
>  > readable). Buildsys runs a slightly modified version that adds a bit more
>  > debug output in this area.
>  
>  Maybe just trap the exception, print it out, and continue?  That way at
>  least the server doesn't fall over, it just fails to copy one item.  
The buildsys runs such a patched Repo.py already. It catches OSError,
IOError, unlocks the locks and prints/logs the results of the file access
check prior to when files are copied.

I also added a debug line in the package job code to see when it starts
deleting the copied files. Normally it waits until a callback tells it
that all files are copied.

>  It might also help debugging to see if only specific files can't
> be
>  copied... 
The offending file was copied, but shutil.copy() failed in its second part
when trying to copy the file mode. It didn't find the source file it had
just copied. :-}

[Michael Schwendt]

On Sun, 30 Dec 2007 17:54:51 +0100, Michael Schwendt wrote:

>  If in a failed job.log you see the message
>  
>      Job waited too long for repo to unlock. Killing it...
>  
>  please notify me.
>  
>  It's a problem in the plague server code that results in a denial of
>  service for subsequent build jobs. I have a traceback from Dec 28th, but
>  in the context of the source code it doesn't make sense yet (because a few
>  lines earlier the code ensures that the files to be copied exist and are
>  readable). Buildsys runs a slightly modified version that adds a bit more
>  debug output in this area. 
Certainly related, job #37767 just failed

  Failed to copy
/srv/rpmbuild/server_work/fedora-5-epel/37767-php-pecl-memcache-2.2.1-1.el5/ppc/php-pecl-memcache-2.2.1-1.el5.ppc.rpm
to the repository directory.

and that should not happen either. I assume this is not the first time
this has happened. The additional debug details are interesting.

In the server log, the individual arch jobs print the list of files
downloaded from the builders. At that time they should be available
already:

  37767 (php-pecl-memcache/ppc): Build result files - [
'php-pecl-memcache-2.2.1-1.el5.ppc.rpm',
'php-pecl-memcache-2.2.1-1.el5.src.rpm', 'root.log',
'php-pecl-memcache-debuginfo-2.2.1-1.el5.ppc.rpm', 'state.log',
'job.log', 'build.log' ]

  37767 (php-pecl-memcache/x86_64): Build result files - [ 'root.log',
'build.log', 'state.log', 'php-pecl-memcache-2.2.1-1.el5.src.rpm',
'php-pecl-memcache-debuginfo-2.2.1-1.el5.x86_64.rpm',
'php-pecl-memcache-2.2.1-1.el5.x86_64.rpm', 'job.log' ]

  37767 (php-pecl-memcache/i386): Build result files - [ 'root.log',
'php-pecl-memcache-debuginfo-2.2.1-1.el5.i386.rpm', 'state.log',
'php-pecl-memcache-2.2.1-1.el5.i386.rpm', 'build.log',
'php-pecl-memcache-2.2.1-1.el5.src.rpm', 'job.log' ]

Further down in the log, the fedora-5-epel repo controller is asked to
install the files into the needsign repo:

  Repo 'fedora-5-epel': updating repository metadata...

At that time, the last of the ppc files is not yet accessible (i.e. it
either doesn't exist or cannot be read):

  [...]
  Repo:
/srv/rpmbuild/server_work/fedora-5-epel/37767-php-pecl-memcache-2.2.1-1.el5/x86_64/php-pecl-memcache-2.2.1-1.el5.x86_64.rpm
is accessible.
  Repo:
/srv/rpmbuild/server_work/fedora-5-epel/37767-php-pecl-memcache-2.2.1-1.el5/ppc/php-pecl-memcache-2.2.1-1.el5.ppc.rpm
is inaccessible.

Further proof-reading of source code necessary... it should not populate
needsign before all files are downloaded.

[Michael Schwendt]

>  Certainly related, job #37767 just failed
>  
>    Failed to copy
> /srv/rpmbuild/server_work/fedora-5-epel/37767-php-pecl-memcache-2.2.1-1.el5/ppc/php-pecl-memcache-2.2.1-1.el5.ppc.rpm
> to the repository directory.
>   
Status update:

A work-around and debug-helper has been applied. I've moved the "does the
downloaded file exist and is readable?" check _in front_ of the downloader
callback. It now checks the downloaded file as early as possible, and if
the check fails, the download is marked as failed, so plague retries
downloading it at most 10 times. If that fails, there is a serious problem
of course (and that's not what we've seen). And if the good download turns
inaccessible later although it had passed the check, that would be *very*
interesting and will appear in the logs. Perhaps this mysterious
download/add_to_repo problem is only a rare bug in threaded Python
and working around it might be the only thing we can do.

[Michael Schwendt]

On Fri, 4 Jan 2008 15:55:56 +0100, Michael Schwendt wrote:

>  > Certainly related, job #37767 just failed
>  > 
>  >   Failed to copy
> /srv/rpmbuild/server_work/fedora-5-epel/37767-php-pecl-memcache-2.2.1-1.el5/ppc/php-pecl-memcache-2.2.1-1.el5.ppc.rpm
> to the repository directory.
>  > 
>  
>  Status update:
>  
>  A work-around and debug-helper has been applied. I've moved the "does the
>  downloaded file exist and is readable?" check _in front_ of the downloader
>  callback. It now checks the downloaded file as early as possible, and if
>  the check fails, the download is marked as failed, so plague retries
>  downloading it at most 10 times. If that fails, there is a serious problem
>  of course (and that's not what we've seen). And if the good download turns
>  inaccessible later although it had passed the check, that would be *very*
>  interesting and will appear in the logs. Perhaps this mysterious
>  download/add_to_repo problem is only a rare bug in threaded Python
>  and working around it might be the only thing we can do. 
I've applied another patch that shall fix the symptoms. (The cause of it
may be related to threads+events.)

While the work-around was good enough to prevent the server from crashing,
build-job 37923 (perl-String-CRC32 for el4) according to the logs did
"copy to needsign repo" twice. That also explains why files downloaded
from a builder are missing suddenly while copying them into the needsign
repo. The first run it copied all files successfully. Then during the
second run one of the files was missing because another thread had started
the related cleanup already. That made the job fail. According to the logs,
the packager requeued the job to build it once more and successfully.

[Dan Williams]

On Fri, 2008-01-18 at 03:56 +0100, Michael Schwendt wrote:
>  On Fri, 4 Jan 2008 15:55:56 +0100, Michael Schwendt wrote:
>  
>  > > Certainly related, job #37767 just failed
>  > > 
>  > >   Failed to copy
> /srv/rpmbuild/server_work/fedora-5-epel/37767-php-pecl-memcache-2.2.1-1.el5/ppc/php-pecl-memcache-2.2.1-1.el5.ppc.rpm
> to the repository directory.
>  > > 
>  > 
>  > Status update:
>  > 
>  > A work-around and debug-helper has been applied. I've moved the "does the
>  > downloaded file exist and is readable?" check _in front_ of the downloader
>  > callback. It now checks the downloaded file as early as possible, and if
>  > the check fails, the download is marked as failed, so plague retries
>  > downloading it at most 10 times. If that fails, there is a serious problem
>  > of course (and that's not what we've seen). And if the good download turns
>  > inaccessible later although it had passed the check, that would be *very*
>  > interesting and will appear in the logs. Perhaps this mysterious
>  > download/add_to_repo problem is only a rare bug in threaded Python
>  > and working around it might be the only thing we can do.
>  
>  I've applied another patch that shall fix the symptoms. (The cause of it
>  may be related to threads+events.)
>  
>  While the work-around was good enough to prevent the server from crashing,
>  build-job 37923 (perl-String-CRC32 for el4) according to the logs did
>  "copy to needsign repo" twice. That also explains why files downloaded
>  from a builder are missing suddenly while copying them into the needsign
>  repo. The first run it copied all files successfully. Then during the
>  second run one of the files was missing because another thread had started
>  the related cleanup already. That made the job fail. According to the logs,
>  the packager requeued the job to build it once more and successfully. 
Sorry about all the threading :)  It was probably a bad idea (threads
usually are), but it did more or less do the job for a few years.
Here's hoping all the EPEL Koji issues can be ironed out so you don't
have to keep poking plague.

Dan