Bug #99133 for Bot-BasicBot: First response of bots based on Bot::BasicBot is very slow

Thu Sep 25 07:51:58 2014 MORITZ [...] cpan.org - Ticket created

CC:	tadzikes [...] gmail.com
Subject:	First response of bots based on Bot::BasicBot is very slow

When a non-trivial bot based on Bot::BasicBot returns a string from method "said", there is a very noticable delay (between 5s and 10s I'd guess) between returning the string, and the bot printing the response in the channel. This delay only happens the first time a non-empty string is returned; it's gone on subsequent executions. Sadly, I can't reproduce the problem with a very simplistic bot; one project that exhibits it is https://github.com/perl6/evalbot/ and can be easily observed by inserting a warn() statement before the return() here: https://github.com/perl6/evalbot/blob/98c9ae5d47f67f87beef212b2f7b1a51177ebd76/evalbot.pl#L270 Observing both the console that the bot runs on an the IRC channel makes the delay obvious. I thought this was a quirk introduced by the weird things that evalbot does, but it seems I'm not alone: http://irclog.perlgeek.de/perl6/2014-09-25#i_9409316

Thu Sep 25 14:20:48 2014 hinrik.sig [...] gmail.com - Correspondence added

I cloned evalbot, configured it and added a simple perl(1) executor (see attached diff). Yet the first reply I got was instantaneous: 18:15:10 -!- evalbothlagh [~p6eval@a83-163-60-106.adsl.xs4all.nl] has joined #testinghlagh 18:16:29 <literal> p5: print 5 18:16:29 <evalbothlagh> p5: OUTPUT«5» So I'm not sure what the issue could be...

Subject:

test.patch

diff --git a/evalbot.pl b/evalbot.pl index 3ab2ffd..5812715 100755 --- a/evalbot.pl +++ b/evalbot.pl @@ -179,6 +179,10 @@ Q:PIR { revision => sub { get_revision_from_file("$home/std/snap/revision")}, nolock => 1, }, + p5 => { + cmd_line => 'perl %program', + nolock => 1, + }, 'p5-to-p6' => { chdir => "$home/Perlito", cmd_line => "perl perlito5.pl --noboilerplate -I./src5/lib -Cperl6 %program", diff --git a/freenode.org.conf b/freenode.org.conf index ed72d8d..bdea931 100644 --- a/freenode.org.conf +++ b/freenode.org.conf @@ -1,5 +1,5 @@ server = irc.freenode.org -channels = perl6 november-wiki swhack dbdi perl6book perl-kr rosettacode moarvm learnprogramming -nick = camelia +channels = testinghlagh +nick = evalbothlagh alt_nicks = p6eval p6_eval pass = WFkuDV17A6Jhj

Thu Sep 25 14:20:48 2014 The RT System itself - Status changed from 'new' to 'open'

Thu Sep 25 14:22:07 2014 hinrik.sig [...] gmail.com - Correspondence added

Oh, actually, if I issue the command right after it goes online, I do get the delay. Interesting....

Thu Sep 25 14:42:37 2014 hinrik.sig [...] gmail.com - Correspondence added

I'm pretty sure this is caused by flood protection in POE::Component::IRC: https://github.com/bingos/poe-component-irc/blob/master/lib/POE/Component/IRC.pm#L1079 If I turn it off, the delay goes away. You can do so by adding the following to your Evalbot->connected() method: $bot->pocoirc->{flood} = 1; Also, you can run the bot with POCOIRC_DEBUG=1 to see the commands it sends to the IRC server. What causes it to delay sending the first reply are the PRIVMSG to nickserv, along with the WHO and MODE commands sent after first join the channel(s). Whether the flood protection code can afford to be less conservative is another issue. It was written ages ago, so it's possible.

Thu Sep 25 15:24:41 2014 moritz [...] faui2k3.org - Correspondence added

CC:	tadzikes [...] gmail.com
Subject:	Re: [rt.cpan.org #99133] First response of bots based on Bot::BasicBot is very slow
Date:	Thu, 25 Sep 2014 21:24:19 +0200
To:	bug-Bot-BasicBot [...] rt.cpan.org, MORITZ [...] cpan.org
From:	Moritz Lenz <moritz [...] faui2k3.org>

Hi, On 25.09.2014 20:42, Hinrik Orn Sigurdsson via RT wrote: Show quoted text

> <URL: https://rt.cpan.org/Ticket/Display.html?id=99133 > > > I'm pretty sure this is caused by flood protection in POE::Component::IRC:

That makes sense. evalbot usually joins several channels, which means it sends many more messages. Show quoted text

> https://github.com/bingos/poe-component-irc/blob/master/lib/POE/Component/IRC.pm#L1079 > > If I turn it off, the delay goes away. You can do so by adding the following to your Evalbot->connected() method: > > $bot->pocoirc->{flood} = 1; > > Also, you can run the bot with POCOIRC_DEBUG=1 to see the commands it sends to the IRC server. What causes it to delay sending the first reply are the PRIVMSG to nickserv, along with the WHO and MODE commands sent after first join the channel(s). > > Whether the flood protection code can afford to be less conservative is another issue. It was written ages ago, so it's possible.

Thanks, I'll experiment with that. Cheers, Moritz

Mon Feb 12 04:51:32 2018 davidp [...] preshweb.co.uk - Correspondence added

Some would consider this a slightly late reply, but yes, I think this is down to flood protection - when the bot hasn't been online for long, it'll be doing a WHO on each channel, etc, so its send queue might be a bit higher - so Poco::IRC's flood protection will be dispatching messages with delays to stop the bot flooding itself off. Once it's "settled in", things should be quicker (unless someone is messaging the bot and prompting it to send multi-line help texts, etc, which could increase the queue again). So, I'd consider this not a bug. I sort of wonder if it could do with a console mode status output that displays statistics (channels joined, send queue length, etc), or the ability to send the same to a status file regularly, as it could make this kind of thing clearer.

Mon Feb 12 04:51:33 2018 davidp [...] preshweb.co.uk - Status changed from 'open' to 'rejected'