Closed Bug 111987 Opened 24 years ago Closed 22 years ago

[mozbot.pl] Mozbot2 randomly times out

Categories

(Webtools Graveyard :: Mozbot, defect, P1)

Product:
Webtools Graveyard
Component:
Mozbot
Platform:
x86
Linux
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: kerz, Assigned: ian)

References

Details

(Keywords: helpwanted, qawanted)

Seems to be timing out either while grabbing tinderbox data, or after getting it. It drops off of irc, but is still running locally. It is running along with a fork of itself. Could the fork not be closing properly?
Severity: normal → critical
OS: Windows 2000 → Linux
Priority: -- → P1
weird. I got timeouts here too, but always when my IRC client _also_ timed out.
has anyone tried this w/ some ircd other than irc.mozilla.org which has been throwing general fits?
Ok, after getting some extra debugging code into kerz' mozbot.pl, we've tracked it down to the following line in said file: $pipe->close(); (This appears in the child section of spawnChild().) The line before it executes, the line after it does not. This results in the pipe back to mozbot's main process never getting closed, and so said process hangs and then times out. I'm at a loss about what the correct solution is, because that's not my code. (Unless the bug is triggered by something in IO::SecurePipe module.)
I've also noticed that it will timeout if somebody throws a query at the bot that returns a /lot/ of results. I watched the debug window and it did complete the query (although it took a long time). However, as soon as that child process returned, mozbot.pl started eating up 90%+ of my CPU (according to top) and wouldn't do anything else. This is presumably because of the regular expressions it's trying to parse the HTML with. I'm working on making the bot use XML instead of getting the HTML from buglist.cgi and trying to parse that, but that only works with single bug queries not the searching interface. Once bug 103778 is fixed, we should be able to make an XML template and then use that instead of the HTML to completly get rid of the HTML parsing attempts.
Depends on: 115642
I've actually seen this once with my local installation now. I can't understand it. In the cases I've seen it (with kerz's bot or the one case on my machine) it was usually a small file, so not anything to do with huge regexps. I think the large regexp stuff is a separate bug.
This also seems to occur only very rarily. Maybe it's an unexpected interaction between perl and the local machine?
WFM now that i cleaned off the machine.
Status: NEW → RESOLVED
Closed: 24 years ago
Resolution: --- → WORKSFORME
QA Contact: timeless → kerz
*** Bug 131484 has been marked as a duplicate of this bug. ***
Reopening... people have been seeing this again. I have no clue what it is, how to reproduce it, or how to fix it.
Status: RESOLVED → REOPENED
Keywords: helpwanted, qawanted
Resolution: WORKSFORME → ---
Target Milestone: --- → Future
Summary: Mozbot2 randomly times out → [mozbot.pl] Mozbot2 randomly times out
I've found a way to recreate the bug, at least on my server. Using the RDF module to retreive news from Slashdot (/msg mozbot vars RDF sites '+|slashdot|http://slashdot.org/slashdot.rdf') works without any problems but when I do /msg mozbot vars RDF sites '+|freshmeat|http://freshmeat.net/backend/fm-releases.rdf', mozbot get's stuck when it tries to fetch the info. It ping timeouts from the server and there are two mozbot processes running. I have not tried to reproduce this with other rdf files.
That reliably reproduces it for me too -- thanks!
i experienced this bug with other rdf files too, for example this bbc world news feed: http://www.newsisfree.com/HPE/xml/feeds/60/60.xml i wonder if this is something specific to the RDF module or an issue in mozbot itself?
If the former, there are two bugs, as I've been seeing this with RDF disabled.
indeed, i am seeing this randomly with the spelling module as well. sometimes when u ask for a word spelling with say mozbot recieve (sp?) the bot will timeout.
Anyone know where exactly (as in, which line number) it is getting stuck on?
Its getting stuck on line 1459 of mozbot.pl "$pipe->close();" Here is how I recreate the bug. 1. start mozbot 2. auth myself 3. vars RDF updateDelay '10' (update every 10 seconds) 4. Add an RDF site to that sites hash 5. Repeat 4 until it hangs consistantly IO::SecurePipe = IO::Pipe = IO::Handle I was reading up on why IO::Handle would hang and it lead me to the Perl Cookbook recipe 16.10 -- Because piped filehandles are not bidirectional, each process uses just one of the pair and closes the filehandle it doesn't use. The reason is subtle; picture the situation where the reader does not close the writable filehandle. If the writer then exits while the reader is trying to read something, the reader will hang forever. This is because the system won't tell the reader that there's no more data to be read until all copies of the writable filehandle are closed. -- I am by no means an expert on dealing the inter process communication, but this may point you into the right direction.
I have a fix... although it comes in the form of a hack :( After reading this node on Perl Monks http://perlmonks.thepen.com/145927.html I put (I still got the hang error with sleep(1)) sleep(2); $pipe->close(); before the $pipe->close(); call and I can't reproduce the bug. Currently am running these RDF sites <mozbot> Variable 'sites' in module 'RDF' is a hash with the following values: <mozbot> 'debianplanet' => 'http://www.debianplanet.org/backend.php' <mozbot> 'freshmeat' => 'http://freshmeat.net/backend/fm.rdf' <mozbot> 'jbisbee.com' => 'http://www.jbisbee.com/rdf/' <mozbot> 'linuxweeklynews' => 'http://lwn.net/headlines/rss' <mozbot> 'newsforge' => 'http://www.newsforge.com/newsforge.rdf' <mozbot> 'perljobs' => 'http://jobs.perl.org/rss/standard.rss' <mozbot> 'slashdot' => 'http://slashdot.org/slashdot.rdf' <mozbot> 'useperl' => 'http://use.perl.org/useperl.rdf' <mozbot> End of dump of variable 'sites'. and I'm updating every 10 seconds with NO hangs what so ever. Where I before I could only go once or twice without things coming to a halt before I killed the offending child process.
hmm... i don't like that very much, as you say, it's a hack ;-) thanks for the work tracking down the problem though, that is _very_ helpful.
the culprit is line 55 of IO::SecurePipe exec { $_[0] } @_ or # XXX change here When I replace all instances of IO::SecurePipe with IO::Pipe, I don't get the hangs (even when I set the RDF updateDelay to '1' and try to overload the bot) As we discussed on #mozwebtools, I'm not sure how or why this would cause 'close' to hang. to be continued... :)
Scrap that soultion... I got it to hang with IO::Pipe too
in spawnChild when the pipe is evaled to wget a $SIG{ALRM} handle needs to be added and an alarm needs to be set eval { local $SIG{ALRM} = sub { die "alarm clock restart" }; alarm 10; # do stuff alarm 0; } This will make sure that if there is a hang, it's only for the number of seconds set by alarm. This also is an answer the the comment: # it would be nice if some of this was on a timeout... in the source :) I have test cases (one with the alarm and one without) here: http://www.jbisbee.com/files/mozbot_fork_no_alarm.pl http://www.jbisbee.com/files/mozbot_fork_alarm.pl I'm sure slashdot and others don't like hammering away at there RDFs like that, but its the only way I could reproduce the bug :)
While I think adding a timeout is not a bad idea, I fail to see why this should fix the bug. The hang is occuring on the master thread. The master thread is only blocked on the forked thread once the forked threat starts sending data back. The forked thread only starts sending data back once the child process has terminated. Therefore it shouldn't matter how long the child process takes, and therefore putting it on a timeout shouldn't fix this bug. So if this idea does indeed fix the bug, why does it do so???
Hmm, just a few minutes ago, thebot (pulled from mozbot trunk) timed out again. The following lines are the last ones that still are on its console output on the server: 2003-02-24 12:47:44 UTC (3734) nosuchnick: thebot #spam No such nick/channel 2003-02-24 12:47:50 UTC (3734) Heard: #mozilla.de <opi> biesi-away: KaiRo will auch was zu tun haben :-) 2003-02-24 12:47:58 UTC (3734) Heard: #mozilla.de <biesi-away> ok :) 2003-02-24 12:48:03 UTC (3734) ->#spam: ping 2003-02-24 12:48:04 UTC (3734) nosuchnick: thebot #spam No such nick/channel 2003-02-24 12:48:23 UTC (3734) ->#spam: ping 2003-02-24 12:48:24 UTC (3734) nosuchnick: thebot #spam No such nick/channel 2003-02-24 12:48:34 UTC (3734) Heard: #mozilla.de <matic> opi: könnte vielleicht auch mit http://bugzilla.mozilla.org/show_bug.cgi?id=93461 zusammenhängen (dein problem) ? 2003-02-24 12:48:34 UTC (3734) Module Bugzilla: Noticed someone mention bug 93461 -- investigating... 2003-02-24 12:48:34 UTC (3734) Module Bugzilla: spawned 27818 (wget --quiet --passive --user-agent="Mozilla/5.0 (compatible; mozbot)" --output-document=- http://bugzilla.mozilla.org/xml.cgi?id=93461) 2003-02-24 12:48:36 UTC (3734) Module Tinderbox: spawned 27820 (wget --quiet --passive --user-agent="Mozilla/5.0 (compatible; mozbot)" --output-document=- http://tinderbox.mozilla.org/showbuilds.cgi?quickparse=1&tree=SeaMonkey,SeaMonkey-Ports,MozillaTest,Grendel) 2003-02-24 12:48:38 UTC (3734) child 27820 completed URI This is what I saw in the channel: [13:51:25] <-- thebot has quit (Ping timeout: 180 seconds) (it looks as it was off one hour, but that's my difference to UTC/GMT, and thebot shows UTC obviously, so it timed out approx. 3 minutes / 180 seconds after its last console message) Hmm, it would be really nice if we could find out what's happening...
Interesting. 1) When it hang, it consumed 0.0% CPU. 2) Hitting ctrl+c on the [screen] console made it terminate normally ("received signal INT. shutting down..."), but the lines went into two (!) mozbot.pl.*.log files with different process numbers, one being the "normal" one, and one being newly created, only containing those shutdown log messages...
I am as baffled as everyone else by this. The next debugging step I can think of would be to run mozbot under trace(1) to see what is going on at that level.
Apparently, this isn't a completely unusual problem, as one can see from http://use.perl.org/~hex/journal/11426. It would seem that the fix is "switch to POE::Component::IRC", as had been planned for a while IIRC.
I'd still like to know what the problem is. I am quite happy to fix Net::IRC if that is necessary.
Another timeout like the one mentioned before, new perl version (5.8.0) that gives an extra message: 2003-05-13 14:13:26 UTC (13018) Module Tinderbox: spawned 14732 (wget --quiet --passive --user-agent="Mozilla/5.0 (compatible; mozbot)" --output-document=- http://tinderbox.mozilla.org/showbuilds.cgi?quickparse=1&tree=SeaMonkey,SeaMonkey-Ports,MozillaTest,Grendel) 2003-05-13 14:13:28 UTC (13018) child 14732 completed URI Use of tainted arguments in exec is deprecated at ./mozbot.pl line 1498 (#2) (D deprecated) The construct indicated is no longer recommended for use, generally because there's a better way to do it, and also because the old way has bad side effects.
please update to the tip and try to see if you can still reproduce this.
Status: REOPENED → RESOLVED
Closed: 24 years ago → 22 years ago
Resolution: --- → FIXED
thebot is updated to the tip now, let's see if it helps :) Thanks for your work!
QA Contact: kerz → mozbot
Target Milestone: Future → 2.6
Product: Webtools → Webtools Graveyard
You need to log in before you can comment on or make changes to this bug.