IRC log of #zope for Tuesday, 2012-09-11

*** motto has joined #zope00:20
*** kosh has joined #zope00:22
*** m8 has quit IRC00:22
*** J1m has quit IRC00:30
*** roq_ has joined #zope01:05
*** thetet has quit IRC01:19
*** Arfrever has joined #zope01:22
*** motto has quit IRC01:33
*** TresEquis has quit IRC01:40
*** mcdonc has quit IRC01:40
*** mcdonc has joined #zope01:41
*** sp0cksbeard has quit IRC01:45
*** supton_ has joined #zope01:48
*** supton has quit IRC01:51
*** fdrake has quit IRC02:00
*** roq_ has quit IRC02:13
*** J1m has joined #zope02:32
*** dayne has joined #zope02:49
*** runyaga has quit IRC02:56
*** _mup_ has quit IRC03:00
*** _mup_ has joined #zope03:00
*** Spanktar has quit IRC03:11
*** J1m has quit IRC03:27
*** tiwula has quit IRC03:30
*** CIA-101 has quit IRC03:42
*** CIA-101 has joined #zope04:12
*** fdrake has joined #zope04:37
*** daMaestro has quit IRC05:02
*** kosh has quit IRC05:11
*** KageSenshi has quit IRC07:22
*** walden_ has joined #zope07:32
*** Deichi has joined #zope08:37
*** nande has quit IRC08:44
*** KageSenshi has joined #zope08:46
*** yvl has joined #zope08:50
*** agroszer has joined #zope09:07
*** tomas has left #zope09:12
*** __mac__ has joined #zope09:21
*** MrTango has joined #zope09:36
*** mitchell`off is now known as mitchell`09:39
*** tisto has joined #zope09:41
*** avoinea has joined #zope09:46
*** giacomos has joined #zope10:06
*** walden_ has quit IRC10:08
*** fredvd has joined #zope10:15
*** fredvd2 has joined #zope10:17
*** fredvd has quit IRC10:17
*** fredvd2 has quit IRC10:45
*** eperez has joined #zope10:46
*** fredvd has joined #zope11:45
*** evilbungle has joined #zope12:07
*** RichyB has joined #zope12:11
*** maurits has joined #zope12:13
*** goschtl has joined #zope12:27
*** teix has joined #zope13:06
*** Zart has left #zope13:14
*** fdrake has quit IRC13:22
*** zagy has joined #zope13:39
*** tisto has quit IRC13:47
*** tisto_ has joined #zope13:47
*** J1m has joined #zope14:08
*** RichyB has quit IRC14:09
*** thetet has joined #zope14:12
*** tisto_ is now known as tisto|lunch14:15
*** kosh has joined #zope14:17
*** M46IST has joined #zope14:21
*** RichyB has joined #zope14:22
*** RichyB has quit IRC14:27
*** RichyB has joined #zope14:28
*** J1m has quit IRC14:40
*** evilbungle has quit IRC14:41
*** evilbungle_ has joined #zope14:41
*** goschtl has quit IRC14:47
*** goschtl has joined #zope14:48
*** fdrake has joined #zope14:49
*** deuterium has joined #zope15:19
deuteriumwhen attaching gdb to the python instance that runs my zope and if i do a "info threads" afterwards, all but two threads are in state sem_wait (). is this to be expected? see
deuteriumthing is that i observe a constantly high cpu load (100%) of the python process running zope, for no obvious reason.15:25
mgedminyeah, waiting for a semaphore sounds right15:26
mgedminif you can hack your zope to provide Python tracebacks of all the threads (using sys._currentframes().values() and traceback.print_stack(f)), that would be more useful than C level stacks15:27
mgedminit should be easily doable from an external method15:27
deuteriummgedmin: i tried to use   call PyRun_SimpleString("import sys, traceback; sys.stderr=open('/tmp/tb','w',0); traceback.print_stack()") from within gdb, but i didn't know which thread i should select15:30
mgedmin"all of them" would be a good start ;)15:31
deuteriumso i didn't do it. but that would print a python traceback, according to
deuteriummgedmin: hm.. how can i select all? ;)15:31
mgedminchange 'traceback.print_stack()' in that example to 'for f in sys._currentframes().values(): traceback.print_stack(f)'15:32
mgedminNB: not tested15:32
mgedminlet me try it out now15:32
mgedminhm, I'm getting a syntax error15:33
mgedminimport sys, traceback; sys.stderr = open('/tmp/tb', 'w', 0); [traceback.print_stack(f) for f in sys._current_frames().values()]15:34
mgedminworks as a one-liner15:34
deuteriumok, nice :) i try this15:34
mgedminalso, you may want to restart that Zope instance at some point, as that oneline you ran permanently leaves sys.stderr redirected to that /tmp file15:34
deuteriumthe thing which somewhat confuses me regarding sem_wait is that man 3 sem_wait states: "If the semaphore's value is greater than zero, then the decrement proceeds, and the function15:35
deuterium       returns, immediately.  If the semaphore currently has the value zero, then the call blocks until either it becomes possible to perform the decrement (i.e.,  the15:35
deuterium       semaphore value rises above zero), or a signal handler interrupts the call."15:35
mgedmina better one-liner would be15:35
deuteriumoops, sorry15:35
mgedminimport sys, traceback; tmpf = open('/tmp/tb', 'w', 0); [traceback.print_stack(f, file=tmpf) for f in sys._current_frames().values()]15:35
deuteriumok, let me try this15:36
mgedminor even15:36
mgedminimport sys, traceback; tmpf = open('/tmp/tb', 'w', 0); [(traceback.print_stack(f, file=tmpf), tmpf.write('---\n')) for f in sys._current_frames().values()]15:36
mgedmin[(None, None)]15:36
mgedminso you can more easily see where each traceback begins and ends15:36
betabugI would try the DeadlockDebugger15:37
mgedminusing gdb + PyRun_SimpleString is a nice trick15:37
betabugwhy reinvent the wheel? it should run on 2.8 too15:37
deuteriumbetabug: ?15:39
deuteriumbetabug: would need to be installed separately, right? can't find it in apt-cache15:40
betabugyes, looks like that is the one15:40
betabugyou put it into the "Products" folder in the instance15:40
mgedminin the meantime, pastebin the tracebacks you've already gotten?15:40
betabugand you have to edit one file inside it (there are instructions)15:40
deuteriumbetabug: i'm first trying mgedmin's one-liner15:40
mgedminoh, I thought you already tried that :)15:40
*** sunew has joined #zope15:41
deuteriummgedmin: well, it's a live system.. i'm very cautious i don't accidentally destroy anything15:41
mgedminyeah... every time I tried to introspect a running Python process with gdb, I managed to make it segfault15:42
betabugdeuterium: so that fake "bing" request wasn't the cause of the high load?15:44
deuteriumbetabug: well, i can't rule this out yet.. i have to block "bingbot" requests on the box using fail2ban indeed.. but actually we filter things on a dedicated firewall and also use a proxy.. unfortunately it can be bypassed, so i have to temporarily filter out the requests on the zope box itself15:47
deuteriummgedmin: (gdb) call PyRun_SimpleString("import sys, traceback; tmpf = open('/tmp/tb', 'w', 0); [(traceback.print_stack(f, file=tmpf), tmpf.write('---\n')) for f in sys._current_frames().values()] [(None, None)]")15:48
deuterium$1 = -115:48
deuteriummgedmin: without selecting a particular thread first (maybe i need to do this?)15:48
deuteriumbut i don't know which thread to select15:49
deuteriumone actually seems to be in select () state already15:49
deuteriumhm.. if i issue a "select 1" first (it's the thread that uses 100% cpu), there's the same error with that one-liner.. must be a typo or syntax error or so, i guess?15:50
deuteriumi.e. there's no /tmp/tb created15:51
*** menesis1 has joined #zope15:52
deuteriumthis one works:15:53
deuteriumcall PyRun_SimpleString("import sys, traceback; tmpf = open('/tmp/tb', 'w', 0); [traceback.print_stack(f, file=tmpf) for f in sys._current_frames().values()]")15:53
deuteriumhm.. tb is empty though15:54
deuteriummaybe i need to tell gdb to continue with executing the thread?15:54
deuteriumah nice, the original one-liner works fine without an error and fills the /tmp/tb file:15:57
deuteriumcall PyRun_SimpleString("import sys, traceback; sys.stderr=open('/tmp/tb','w',0); traceback.print_stack()")15:57
mgedminwhich Python?16:03
mgedmini.e. which Python version do you have?16:03
mgedminsys._current_frames() appeared in 2.516:04
*** les_sylvains has joined #zope16:04
*** RichyB has quit IRC16:05
*** kosh has quit IRC16:06
*** J1m has joined #zope16:10
deuteriummgedmin: python 2.3.616:11
deuteriumand here's the traceback from /tmp/tb with the original one-liner:
deuteriumi've no idea whether there's any indication of a high cpu load in this traceback?16:13
mgedminhard to say, it looks like a normal transaction commit16:13
mgedminhow many requests per second is the server handling?16:13
deuteriumin the instance logs, i strangely see requests from (alleged, perhaps) search bots only.. like "bingbot", Googlebot etc. at about 1 request per second. cpu load is 100%16:14
deuteriumshould i try the first or rather try blocking the "bingbot" etc. requests?16:24
deuteriumbetabug: is the deadlockdebugger useful to find out which threads create the 100% cpu load?16:24
betabugI would think so16:25
deuteriumok, i try this16:25
betabugin  my experience you want to block that fake bot in any case16:26
deuteriumhm.. there's no documentation though and the deadlockdebugger is from 200516:26
deuteriumbetabug: ok, i'll try that first.. using fail2ban locally on the zope server16:26
betabugdeuterium: your zope isn't any newer16:27
betabugthe documentation is in the REQDME.txt IIRC16:27
betabugdeuterium: also maybe did you try running a copy of the site on another host and see if that goes to 100% too?16:28
mgedminmaybe block all HTTP requests for 10 minutes, see if the load drops to 0?16:29
deuteriumbetabug: already migrated the whole server from a physical server to a (now) virtual server, but the high cpu load remained, thought the whole hardware below should allow for double the performance, all in all.16:30
mgedminI see that DeadlockDebugger depends on
betabugyeah, what mgedmin said then... or make a copy of the vm and try it there first16:30
deuteriumbetabug: i thus really thing there's something with that zope instance.. or it might be a disguised attack indeed16:30
mgedminso it should work on your ancient Python16:30
*** RichyB has joined #zope16:31
deuteriummgedmin: ok16:31
deuteriumi'm trying to block the *bots16:31
betabugI have some experience with DeadlockDebugger, it helped me solve some problem with another old zope a year ago16:31
*** evilbungle_ has quit IRC16:35
*** evilbungle has joined #zope16:36
*** sp0cksbeard has joined #zope16:41
*** evilbungle_ has joined #zope16:41
*** evilbungle has quit IRC16:42
*** evilbungle_ is now known as evilbungle16:42
*** roq_ has joined #zope16:42
deuteriumi'm currently writing the fail2ban rule for blocking the bots16:50
deuteriumaccording to the zope instance's log, there are currently quite a few "normal" requests to be handled as well.. i'd say about 3-6 per second. justifies 100% cpu load?16:51
*** les_sylvains has left #zope16:52
*** menesis1 has quit IRC16:55
betabugno, I think there is something fishy16:57
betabugmaybe it's looking for some external resource or so16:57
betabugI'd look at how long these requests take16:57
betabugand at the profiler in the Control_panel, maybe you can spot what they are doing there16:58
betabuganyway, I'm off for a swim now, good luck for the moment :-)16:58
*** menesis has joined #zope17:02
*** goschtl has quit IRC17:02
deuteriumbetabug: ok, thanks a lot for the hint! have a nice swim (outdoor baths are mostly closed in zurich already ;)17:03
*** Deichi has quit IRC17:04
*** dayne has quit IRC17:11
*** thetet has quit IRC17:19
*** menesis has quit IRC17:27
*** menesis has joined #zope17:27
deuteriumi just wonder, where the profile is in the control panel? maybe /Control_Panel/DebugInfo? /cc mgedmin17:37
mgedmineh, I dunno17:38
mgedminyou should /cc betabug on this17:38
deuteriummgedmin: he's off swimming, lol17:38
* deuterium should actually do this too.. it's the last warm day in .ch ;)17:39
deuteriummgedmin: "Top Refcounts" is the number of calls to that function?17:39
mgedminno, that looks like memory usage stats17:40
deuteriumhm.. can't find any information there about long-running or cpu intensive threads (or requests)17:41
mgedminhave you installed DeadlockDebugger yet?17:41
deuteriumah lol, i found the profiler.. it's simply the other tab there17:42
deuterium"Profiling is not currently enabled or there is not yet any profiling data to report. To enable profiling, restart the Zope process with the configuration setting 'publisher-profile-file' defined. The value of this variable should be the full system path to a file that will be used to dump a profile report when the process restarts or exits."17:42
deuteriummgedmin: no, haven't installed it yet17:42
deuteriumi think i'll try the profiler first17:43
*** __mac__ has quit IRC17:49
deuterium"In order to use profiling Zope has to be started with the PROFILE_PUBLISHER environment variable set to a non-empty value."17:50
deuteriummgedmin: is this a normal system environment variable that i can set simply before starting zope?17:50
*** daMaestro has joined #zope17:51
mgedminI wonder what negative side effects it has...17:51
* mgedmin never used the Zope 2 profiler17:51
deuteriumslows down the system temporarily17:51
deuteriumi.e. zope, i meant17:52
mgedminall of the requests, or just while you have profiling enabled?17:52
deuteriumbtw, looks like it can also be set in <environment></environment>17:52
deuteriumwhile having it enabled17:52
deuteriumbut a restart seems to be required17:52
*** sunew has quit IRC18:02
*** nande has joined #zope18:03
deuteriumhm.. strangely, the profiling tab in zmi doesn't show any information, though i've defined PROFILE_PUBLISHER /var/lib/zope/instance/elk9/log/profiler.log in the conf files <environment></environment>18:12
*** zagy has quit IRC18:27
deuteriumenabling the profiler simply doesn't work.. there's no information displayed neither in the tab nor is there any log file created18:28
deuteriumi've also defined an according system var, doesn't have any effect upon restarting zope either18:28
*** tisto|lunch has quit IRC18:40
*** agroszer has quit IRC18:41
*** alecm has quit IRC18:44
*** alecm has joined #zope18:49
*** supton has joined #zope18:49
*** giacomos has quit IRC19:13
*** maurits has quit IRC19:14
*** fredvd has quit IRC19:16
*** fredvd has joined #zope19:16
*** fredvd has quit IRC19:21
betabugdeuterium: dunno about the profiler19:24
betabugI thought it was easy to enable, but can't remember how I did it19:25
deuteriumbetabug: hm.. it's supposed to be easy to enable.. just set an environment var. or set it in the zope.conf file. unfortunately, that didn't work though.19:26
deuteriumit's strange, yes19:26
betabugas for swimming, it was a bit cool in the sea, as we were a bit late :-)19:26
deuteriumwell, i have to continue debugging this later19:26
deuteriumyou were in the sea? ;)19:27
deuteriumi guess lake, right?19:27
deuteriumlake of zurich?19:27
betabugI'm in .gr19:27
deuteriumoh my19:27
deuteriumthat's nice for sure19:27
betabugon Naxos right now - but I'm actually from .ch myself19:27
deuteriumhow many degrees?19:27
betabugdunno the temperature19:27
betabugI'm still running around in shorts, but in the evenigs I started to put on a shirt19:28
deuteriumstill much warmer than here, i guess.. water temp is around 20 °C only, afaik19:28
betabug20c would be pretty good for Zuerich19:29
deuteriumok.. i should go on vacation too.. should go more southwards then, i guess.. egypt, maybe19:29
betabugdepends if you still want to go to swim, yes19:29
betabughere at the end of the month I think the swimming will be over19:29
* deuterium hasn't had any summer vacation yet19:29
deuteriumoh ok19:30
deuteriumwell, enjoy it, then!19:30
*** Spanktar has joined #zope19:31
*** Spanktar has joined #zope19:32
betabugwell, I didn't have any summer vacatioin yet either, but I managed to go for swims some times after work :-)19:32
deuteriumthanks mgedmin & betabug! bbl19:38
*** deuterium has quit IRC19:42
*** m8 has joined #zope19:53
*** menesis has quit IRC19:59
*** MrTango has quit IRC20:04
*** evilbungle_ has joined #zope20:06
*** agroszer has joined #zope20:06
*** evilbungle has quit IRC20:10
*** evilbungle_ is now known as evilbungle20:10
*** deuterium has joined #zope20:12
*** zenwryly has quit IRC20:18
*** zenwryly has joined #zope20:19
*** avoinea has quit IRC20:22
*** eperez has quit IRC20:31
*** zenwryly has quit IRC20:38
*** zenwryly has joined #zope20:39
*** menesis has joined #zope20:44
*** evilbungle has quit IRC20:45
*** tiwula has joined #zope20:49
*** agroszer has quit IRC20:54
*** zenwryly has quit IRC20:57
*** zenwryly has joined #zope20:57
*** RichyB has quit IRC21:14
*** mitchell` is now known as mitchell`off21:15
*** zenwryly has quit IRC21:17
*** zenwryly has joined #zope21:17
*** kosh has joined #zope21:31
*** tiwula has quit IRC21:32
*** tiwula has joined #zope21:50
*** teix has quit IRC21:57
*** polysix has quit IRC21:57
*** mgedmin has quit IRC21:57
*** teix has joined #zope21:58
*** polysix has joined #zope21:58
*** mgedmin has joined #zope21:58
*** polysix has quit IRC21:59
*** polysix has joined #zope21:59
*** KageSenshi has quit IRC22:05
*** teix has quit IRC22:38
*** nande has quit IRC22:45
*** M46IST has left #zope22:56
*** menesis has quit IRC23:22
*** m8 has quit IRC23:34
*** supton_ has joined #zope23:50
*** supton_ has quit IRC23:50
*** supton has quit IRC23:54

Generated by 2.15.1 by Marius Gedminas - find it at!