#339 process-git-requests is partially failing
Closed: Fixed None Opened 9 years ago by limb.

I've run this this morning over several packages, and after the run over 20+ packages it reported that I needed to run /usr/local/bin/pkgdb2branch.py on pkgs.fedoraproject.org on all of them. I did, and it reported that each package was not found, presumably in pkgdb. It is indeed failing to create the git repos/branches, so I suspect there was some change either in pkgdb, pkgdb2branch.py, or there's a problem connecting to it from pkgs. The process-git-requests script has not changed. This worked as of Thursday 10/30, and does not as of today, 11/3.


The set of affected packages appears to include:
jcsp
qm-dsp
riemann-c-client
python-fontname
python-slugify
xfce4-hamster-plugin
tracer
ciphertest
jmatio
mMass

Since we are in freeze pkgdb itself didn't change either.

At least I confirm that the package were not created on pkgdb.

We had a big load spike on proxy01 (which all the internal hosts use for admin and apps).

Perhaps that caused it to not be able to talk to pkgdb?

Can you try one now and see if it works?

Running pkgdb2branch on jmatio failed, so it looks like it wasn't created in pkgdb. I ran process-git-requests. There were 2. perl-Tangerine appears to have succeeded but xfce4-hamster-plugin had had the fedora-cvs flag reset and it failed again with the same error.

So do you get any errors? Or it just says everything is great, but nothing happens?

From the logs on pkgdb, it seems that went through:
perl-Tangerine el7
qm-vamp-plugins master f21, f20, el6, epel7

That's it for today

Replying to [comment:6 kevin]:

So do you get any errors? Or it just says everything is great, but nothing happens?

The pkgdb portion fails silently, the pkgdb2branch.py failure is a Python stacktrace ending in

pkgdb2client.PkgDBException: Package: xfce4-hamster-plugin not found

so I think it's pkgdb part that's the culprit, but it doesn't really tell me anything.

process-git-requests seems to have a --debug, maybe it could give us some more information.

xfce4-hamster-plugin came through again, ran process-git-requests --debug, got the same result, just the previous error for pkgdb2client.py.

Let me try from here and see if I get the same thing.

pkgdb2client stores the cookie to log on pkgdb in a pickle file in {{{~/.cache/pkgdb-session.pickle}}}

Maybe we could try to delete/rename this file. It should then ask you for a username/password at the first run and not after.

Otherwise I sent to the rel-eng list a couple of patches that might give us some more debugging output: https://lists.fedoraproject.org/pipermail/rel-eng/2014-November/018762.html

Since now everyone is running the script, it did not verify the PKGDB2 certificate until now, so I recommend that everyone who ran the script changes their FAS credentials.

I removed my ~/.cache/pkgdb-session.pickle and ran the updated process-git-requests and of course there are no requests.

Running pkgdb2branch on xfce4-hamster-plugin worked, but failed on jmatio.

Kevin created xfce4-hamster-plugin on pkgdb, so that's expected that it works

The problem really lays in process-git-requests, pkgdb2branch seems to work afaiu

What's interesting is that at for the pkgdb calls in the script, at lines, 622 and 756 it should throw an exception if it's failing, and it isn't. Might there be something telling in the pkgdb server logs?

Looking at the error_log the only errors I see are:
{{{
[Mon Nov 03 14:39:10 2014] [error] [client 10.5.126.52] mod_wsgi (pid=31783): Exception occurred processing WSGI script '/var/www/pkgdb2.wsgi'.
[Mon Nov 03 14:39:10 2014] [error] [client 10.5.126.52] IOError: failed to write data
[Tue Nov 04 01:11:58 2014] [error] [client 10.5.126.52] mod_wsgi (pid=2949): Exception occurred processing WSGI script '/var/www/pkgdb2.wsgi'.
[Tue Nov 04 01:11:58 2014] [error] [client 10.5.126.52] IOError: failed to write data
}}}

And few
{{{
[Mon Nov 03 14:39:05 2014] [error] [client 192.168.1.14] Script timed out before returning headers: pkgdb2.wsgi
[Mon Nov 03 14:39:06 2014] [error] [client 192.168.1.52] Script timed out before returning headers: pkgdb2.wsgi
}}}
Which are I think related to bugzilla and vcs API calls

Looking at the access_log I found:
{{{
192.168.1.63 - - [03/Nov/2014:13:14:53 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.63 - - [03/Nov/2014:13:15:20 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.63 - - [03/Nov/2014:13:15:48 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
10.5.126.52 - - [03/Nov/2014:13:20:17 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
10.5.126.52 - - [03/Nov/2014:13:20:54 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
10.5.126.52 - - [03/Nov/2014:13:40:22 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 200 64 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:41:52 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:42:42 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:49:43 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:50:09 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:50:37 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:55:26 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:55:50 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:56:13 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:13:57:46 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:13:58:26 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:14:00:02 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:14:00:50 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:14:01:09 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
10.5.126.52 - - [03/Nov/2014:14:03:45 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
10.5.126.52 - - [03/Nov/2014:14:04:09 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
10.5.126.52 - - [03/Nov/2014:14:04:33 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.14 - - [03/Nov/2014:14:15:49 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.14 - - [03/Nov/2014:14:16:04 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.14 - - [03/Nov/2014:14:16:28 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:16:03:07 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:16:03:41 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:16:43:29 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:16:44:04 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:16:44:42 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:16:45:12 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"

and

192.168.1.63 - - [03/Nov/2014:13:15:08 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.63 - - [03/Nov/2014:13:15:39 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
10.5.126.52 - - [03/Nov/2014:13:20:08 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
10.5.126.52 - - [03/Nov/2014:13:20:43 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
10.5.126.52 - - [03/Nov/2014:13:21:09 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:41:41 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:42:13 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:42:28 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:49:57 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:50:53 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:55:39 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:13:56:03 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:13:57:36 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:13:58:13 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:13:58:42 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:14:00:19 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.7 - - [03/Nov/2014:14:00:38 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
10.5.126.52 - - [03/Nov/2014:14:03:59 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
10.5.126.52 - - [03/Nov/2014:14:04:23 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.14 - - [03/Nov/2014:14:15:39 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.14 - - [03/Nov/2014:14:16:19 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:16:02:54 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:16:03:22 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:16:04:02 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.78 - - [03/Nov/2014:16:44:24 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 302 385 "-" "python-requests/1.2.3 CPython/2.7.5 Linux/3.16.6-203.fc20.x86_64"
192.168.1.12 - - [03/Nov/2014:17:07:47 +0000] "POST /pkgdb/api/package/new/ HTTP/1.0" 200 64 "-" "python-requests/2.3.0 CPython/2.7.8 Linux/3.18.0-0.rc2.git3.1.fc22.x86_64"
}}}

If I read this correctly the last entry returning a 200 would be Kevin creating the package xfce4-hamster-plugin in pkgdb, the other calls would then be limb being redirected, possibly to the login page.

Interesting. I did a run this morning and it worked for all 28, no errors, after applying pingou's patch from the list. Then I did another run without the patch and it processed qm-dsp with no errors.

So, the problem seems to be gone for some reason. Should I still commit pingou's patch? Seems like a good idea.

Correction, it doesn't look like all of pingou's patch applied, so I can't say whether it works or not.

The patches I sent are only eventually helping to get more info, they shouldn't do anything bu increase the info output by the script.

So I'm really wondering why it worked today and not on Monday :-s

That makes two of us. I'm not comfortable with fixes without explanations.

Running flawlessly most of yesterday and today, before and after pingou's patches. . .closing.

Hopefully next time with --debug we'll know more what the problem is :)

Metadata Update from @limb:
- Issue set to the milestone: Fedora 20 Final

7 years ago

Login to comment on this ticket.

Metadata