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.
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.
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@redhat.com https://www.redhat.com/mailman/listinfo/fedora-buildsys-list
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. :-}
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.
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.
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.
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
buildsys@lists.fedoraproject.org
-
Dan Williams -
Jonathan Dieter -
Michael Schwendt