Bug (or something) repeatedly loading the same URL over and over.
I just saw a thing that I've seen a few times before, and have heard anecdotally that others have too. The problem is that something hits the same URL over and over, eventually knocking over the server. I have some theories, but they're hard to test because this is a rare thing to happen, so I want to see if anyone else has seen something like this. It seems like some kind of search complete or similar running, however CircAutocompl is off. This is a 3.6 machine, though I think I've also seen it on 3.8. Haven't had anything higher running in prod long enough to tell. The log is below. I've reordered it to be when the request is issued rather than when it finishes to make it clearer, and added my speculation in. This is a real request by a human to view details. 172.20.2.200 - - [27/Sep/2013:13:29:01 +1200] "GET /cgi-bin/koha/members/moremember.pl?borrowernumber=16653 HTTP/1.1" 200 7202 This is some kind of automatic process that autocompletes, or something, that's going out of control. There's more of them, but you get the drift: 172.20.2.200 - - [27/Sep/2013:13:29:06 +1200] "POST /cgi-bin/koha/members/member.pl HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:07 +1200] "POST /cgi-bin/koha/members/member.pl HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:07 +1200] "POST /cgi-bin/koha/members/member.pl HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:07 +1200] "POST /cgi-bin/koha/members/member.pl HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:07 +1200] "POST /cgi-bin/koha/members/member.pl HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:07 +1200] "POST /cgi-bin/koha/members/member.pl HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:09 +1200] "POST /cgi-bin/koha/members/member.pl HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:07 +1200] "POST /cgi-bin/koha/members/member.pl HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:07 +1200] "POST /cgi-bin/koha/members/member.pl HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:09 +1200] "POST /cgi-bin/koha/members/member.pl HTTP/1.1" 504 270 I don't know what this is or what it's doing here: 172.20.2.200 - - [27/Sep/2013:13:29:11 +1200] "GET /cgi-bin/koha/circ/circulation.pl?borrowernumber=16653 HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:18 +1200] "GET /cgi-bin/koha/circ/circulation.pl?borrowernumber=16653 HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:10 +1200] "GET /cgi-bin/koha/circ/circulation.pl?borrowernumber=16653 HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:12 +1200] "GET /cgi-bin/koha/circ/circulation.pl?borrowernumber=16653 HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:10 +1200] "GET /cgi-bin/koha/circ/circulation.pl?borrowernumber=16653 HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:13 +1200] "GET /cgi-bin/koha/circ/circulation.pl?borrowernumber=16653 HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:11 +1200] "GET /cgi-bin/koha/circ/circulation.pl?borrowernumber=16653 HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:11 +1200] "GET /cgi-bin/koha/circ/circulation.pl?borrowernumber=16653 HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:12 +1200] "GET /cgi-bin/koha/circ/circulation.pl?borrowernumber=16653 HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:13 +1200] "GET /cgi-bin/koha/circ/circulation.pl?borrowernumber=16653 HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:12 +1200] "GET /cgi-bin/koha/circ/circulation.pl?borrowernumber=16653 HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:17 +1200] "GET /cgi-bin/koha/circ/circulation.pl?borrowernumber=16653 HTTP/1.1" 504 270 172.20.2.200 - - [27/Sep/2013:13:29:16 +1200] "GET /cgi-bin/koha/circ/circulation.pl?borrowernumber=16653 HTTP/1.1" 504 270 It just keeps going like this until I stop apache, and when I start it up again, this doesn't immediately recur. My theory is that there's some javascript somewhere that just loses it and goes mad, but I don't know. Any ideas? This only comes up once every few months, but when it does, it can take the server down. -- Robin Sheat Catalyst IT Ltd. ✆ +64 4 803 2204 GPG: 5FA7 4B49 1E4D CAA4 4C38 8505 77F5 B724 F871 3BDF
Hi, On Thu, Sep 26, 2013 at 7:36 PM, Robin Sheat <robin@catalyst.net.nz> wrote:
It just keeps going like this until I stop apache, and when I start it up again, this doesn't immediately recur.
My theory is that there's some javascript somewhere that just loses it and goes mad, but I don't know. Any ideas? This only comes up once every few months, but when it does, it can take the server down.
I was able to make this happen by performing a patron search and not releasing the enter key for a few seconds. I'll check logs once my test VM recovers. :) Regards, Galen -- Galen Charlton Manager of Implementation Equinox Software, Inc. / The Open Source Experts email: gmc@esilibrary.com direct: +1 770-709-5581 cell: +1 404-984-4366 skype: gmcharlt web: http://www.esilibrary.com/ Supporting Koha and Evergreen: http://koha-community.org & http://evergreen-ils.org
Hi, On Fri, Sep 27, 2013 at 11:08 AM, Galen Charlton <gmc@esilibrary.com> wrote:
I was able to make this happen by performing a patron search and not releasing the enter key for a few seconds.
I'll check logs once my test VM recovers. :)
What ended up showing up in my logs was the repeated POSTs to member.pl, though not any GETs of circulation.pl. Regards, Galen -- Galen Charlton Manager of Implementation Equinox Software, Inc. / The Open Source Experts email: gmc@esilibrary.com direct: +1 770-709-5581 cell: +1 404-984-4366 skype: gmcharlt web: http://www.esilibrary.com/ Supporting Koha and Evergreen: http://koha-community.org & http://evergreen-ils.org
Hi, On Fri, Sep 27, 2013 at 12:33 PM, Galen Charlton <gmc@esilibrary.com> wrote:
What ended up showing up in my logs was the repeated POSTs to member.pl, though not any GETs of circulation.pl.
Adapting a JavaScript technique [1] to disable multiple form submission prevented holding down on the enter key from spamming patron searches for me. Of course, that's not a bulletproof technique for various reasons, but something like it should probably be part of Koha's toolkit. A similar issue in Evergreen where holding down on the enter key could spam OPAC searches was addressed by interposing a short-term cache for running search queries so that if a bunch of identical queries arrive, only one of them queries the database while the rest wait for the first to populate the search result cache. [1] http://stackoverflow.com/questions/926816/how-to-prevent-multiple-form-submi... [2] https://bugs.launchpad.net/evergreen/+bug/1172936 Regards, Galen -- Galen Charlton Manager of Implementation Equinox Software, Inc. / The Open Source Experts email: gmc@esilibrary.com direct: +1 770-709-5581 cell: +1 404-984-4366 skype: gmcharlt web: http://www.esilibrary.com/ Supporting Koha and Evergreen: http://koha-community.org & http://evergreen-ils.org
op 28-09-13 07:45, Galen Charlton schreef:
Adapting a JavaScript technique [1] to disable multiple form submission prevented holding down on the enter key from spamming patron searches for me. Of course, that's not a bulletproof technique for various reasons, but something like it should probably be part of Koha's toolkit.
I'm not completely convinced that it's someone holding down enter on the search form. However, if it is, or if it's something that has that effect, blocking multiple submits seems like a good defensive approach anyway. Robin.
This has just starting happening to one of our sites. While I can recreate a server crash by holding down the enter key on certain pages I am not certain this is the issue. When holding down the enter key and forcing a crash I can see the apache logs showing multiple posts. The kernel log shows the end result of a server crash and OOM starts picking off processes, as expected. However, when the event happens in the wild, so to speak, there isn't anything unusual about the apache logs. The syslog show the details below suggesting opac-main.pl is the culprit but I am struggling to find any form that posts to opac-main.pl in order to cause multipl form submissions. /var/log/syslog.1:Oct 1 11:49:26 srv1 kernel: opac-main.pl invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0, oom_score_adj=0 /var/log/syslog.1:Oct 1 11:49:26 srv1 kernel: [<c10a3408>] oom_kill_process+0x68/0x220 /var/log/syslog.1:Oct 1 11:49:26 srv1 kernel: Out of memory: Kill process 6774 (mysqld) score 42 or sacrifice child /var/log/syslog.1:Oct 1 11:49:26 srv1 kernel: Killed process 6774 (mysqld) total-vm:335720kB, anon-rss:183608kB, file-rss:0kB /var/log/syslog.1:Oct 1 11:49:26 srv1 kernel: init: mysql main process (6774) killed by KILL signal Regards Barry On Sat, Sep 28, 2013 at 6:16 AM, Robin Sheat <robin@catalyst.net.nz> wrote:
op 28-09-13 07:45, Galen Charlton schreef:
Adapting a JavaScript technique [1] to disable multiple form submission prevented holding down on the enter key from spamming patron searches for me. Of course, that's not a bulletproof technique for various reasons, but something like it should probably be part of Koha's toolkit.
I'm not completely convinced that it's someone holding down enter on the search form. However, if it is, or if it's something that has that effect, blocking multiple submits seems like a good defensive approach anyway.
Robin.
_______________________________________________ Koha-devel mailing list Koha-devel@lists.koha-community.org http://lists.koha-community.org/cgi-bin/mailman/listinfo/koha-devel website : http://www.koha-community.org/ git : http://git.koha-community.org/ bugs : http://bugs.koha-community.org/
On Wed, Oct 02, 2013 at 10:51:05AM +0100, Barry Cannon wrote:
However, when the event happens in the wild, so to speak, there isn't anything unusual about the apache logs. The syslog show the details below suggesting opac-main.pl is the culprit but I am struggling to find any form that posts to opac-main.pl in order to cause multipl form submissions.
If a session gets restarted that would call opac-main.pl. I wonder if something has failed/blown up without logging and what we are seeing here is an attempt to restart an opac session after some other part of the system has caused the damage silently. Colin -- Colin Campbell Chief Software Engineer, PTFS Europe Limited Content Management and Library Solutions +44 (0) 800 756 6803 (phone) +44 (0) 7759 633626 (mobile) colin.campbell@ptfs-europe.com skype: colin_campbell2 http://www.ptfs-europe.com
Barry Cannon schreef op wo 02-10-2013 om 10:51 [+0100]:
The syslog show the details below suggesting opac-main.pl is the culprit but I am struggling to find any form that posts to opac-main.pl in order to cause multipl form submissions.
The syslog just shows what was killed, it's not necessarily (but still quite possibly) the same thing that is causing the problem. The apache logs are probably more useful. A note about the apache logs: * the log line is written to the file when the request finishes, * the timestamp in the log line is from when the request was received. This means that a 30-second request can show after stuff that has a later time, and can be quite confusing at first glance. -- Robin Sheat Catalyst IT Ltd. ✆ +64 4 803 2204 GPG: 5FA7 4B49 1E4D CAA4 4C38 8505 77F5 B724 F871 3BDF
participants (4)
-
Barry Cannon -
Colin Campbell -
Galen Charlton -
Robin Sheat