I gave the bot a try in a channel on quakenet, it kept reconnecting ALOT, switched to freenode to see if it was irc network related issue, it was.

It works great on freenode, no reconnects and all is fine.

I switched back to quakenet and the problems started again.
I started it like this "drush start-bot > bot.log" and waited for the reconnects, after looking through the log i found this:

May 08 10:23:58 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 10:24:13 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 10:24:28 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 10:24:43 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 10:24:57 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron->invoke"
May 08 10:24:57 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_faster->invoke"
May 08 10:24:58 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 10:25:13 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 10:25:14 SmartIRC.php(1833) DEBUG_CONNECTION: receive timeout detected, doing reconnect...
May 08 10:25:14 SmartIRC.php(2373) DEBUG_CONNECTION: delaying reconnect for 10000 ms
May 08 10:25:24 SmartIRC.php(1147) DEBUG_CONNECTION: reconnecting...
May 08 10:25:24 SmartIRC.php(1111) DEBUG_CONNECTION: disconnected
May 08 10:25:24 SmartIRC.php(1119) DEBUG_CHANNELSYNCING: cleaned channel array
May 08 10:25:24 SmartIRC.php(1031) DEBUG_CONNECTION: connecting
May 08 10:25:24 SmartIRC.php(1040) DEBUG_SOCKET: using fsockets
May 08 10:25:24 SmartIRC.php(1065) DEBUG_CONNECTION: connected
May 08 10:25:24 SmartIRC.php(1071) DEBUG_SOCKET: activating nonblocking fsocket mode
May 08 10:25:24 SmartIRC.php(1188) DEBUG_CONNECTION: logging in
May 08 10:25:24 SmartIRC.php(1856) DEBUG_IRCMESSAGES: sent: "PASS "
May 08 10:25:24 SmartIRC.php(1205) DEBUG_NOTICE: login() usermode (i) is not valid, will use 0 instead

Any idea why it times out?

Comments

morbus iff’s picture

Status: Active » Postponed (maintainer needs more info)

Is the channel the bot is connecting to full of people coming and going, or with lots of different activity? Does the bot stay connected any longer when there's lots of people active in the channel? My initial suspicion here is that the bot doesn't have anything to do and, as such, thinks that nothing is happening on the server. This manifests as a receive timeout - it hasn't received anything from the server for 10 seconds, so it thinks the server isn't there anymore, necessitating a timeout. A simple way to test this is to get the bot in a channel and just type a period every 5 seconds or so. If the bot doesn't disconnect/reconnect while you're doing that, then we're probably on the right track. This likely doesn't happen in Freenode-land because their server pings connected clients on a regular basis.

kieeps’s picture

You might be on to something, i'w been writing something in the channel every other minute and it hasn't droped once.

Although i found this in the log:

May 08 13:57:13 SmartIRC.php(1935) DEBUG_IRCMESSAGES: received: "PING :servercentral.il.us.quakenet.org"
May 08 13:57:13 SmartIRC.php(2309) DEBUG_MESSAGEHANDLER: calling internal method "Net_SmartIRC->_event_ping" (by string)
May 08 13:57:13 SmartIRC.php(2027) DEBUG_CONNECTION: Ping? Pong!
May 08 13:57:13 SmartIRC.php(1856) DEBUG_IRCMESSAGES: sent: "PONG :servercentral.il.us.quakenet.org"
May 08 13:57:15 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 13:57:21 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_faster->invoke"
May 08 13:57:30 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 13:57:45 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 13:58:00 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 13:58:15 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 13:58:21 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_faster->invoke"
May 08 13:58:30 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 13:58:43 SmartIRC.php(1935) DEBUG_IRCMESSAGES: received: "PING :servercentral.il.us.quakenet.org"
May 08 13:58:43 SmartIRC.php(2309) DEBUG_MESSAGEHANDLER: calling internal method "Net_SmartIRC->_event_ping" (by string)
May 08 13:58:43 SmartIRC.php(2027) DEBUG_CONNECTION: Ping? Pong!
May 08 13:58:43 SmartIRC.php(1856) DEBUG_IRCMESSAGES: sent: "PONG :servercentral.il.us.quakenet.org"
May 08 13:58:45 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 13:59:00 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 13:59:15 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 13:59:21 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_faster->invoke"
May 08 13:59:30 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 13:59:45 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 14:00:00 SmartIRC.php(1815) DEBUG_TIMEHANDLER: calling method "bot_irc_bot_cron_fastest->invoke"
May 08 14:00:13 SmartIRC.php(1935) DEBUG_IRCMESSAGES: received: "PING :servercentral.il.us.quakenet.org"
May 08 14:00:13 SmartIRC.php(2309) DEBUG_MESSAGEHANDLER: calling internal method "Net_SmartIRC->_event_ping" (by string)
May 08 14:00:13 SmartIRC.php(2027) DEBUG_CONNECTION: Ping? Pong!
May 08 14:00:13 SmartIRC.php(1856) DEBUG_IRCMESSAGES: sent: "PONG :servercentral.il.us.quakenet.org"

So it seems as if quakenet also pings connected clients, is it possible to change the timeout the bot tracks before it reconnects? maby the timeout is set lower then the quakenet ping commands.

morbus iff’s picture

I don't actually know how long the Freenode server ping is, but it looks ilk the Quakenet one is every 30 seconds.

Incidentally, I read the library code wrong - the default receiveTimeout in SmartIRC (the underlying IRC library I use) is 5 minutes. So I'm not entirely sure that the receiveTimeout is the issue anymore (even though it certainly looks like that in the debug logs). When the bot was going crazy and reconnecting itself all the time, how many minutes were passing in between it?

If you're a code tweaker, open up bot.smartirc.inc and right around line 30, after:

  $irc->setChannelSyncing(TRUE); // keep a list of joined users per channel.

add the following:

  $irc->setReceiveTimeout(600);

That would set the timeout to 10 minutes, instead of 5.

kieeps’s picture

OK, since i came home from work i'w been trying to figure out how quakenet handles this....as you figured out keeping it alive by having activity in the channel did solve it, but it wont be much activity so kinda need some other fix. i thought i had it all figured out for a while there but seems like i did not, this is what i came up with:

changing the setReceiveTimeout Methode did not help at all, it took 5 minutes and the bot droped again, no pings from the server.
http://pastebin.com/nJPqryVE <-- log as seen before

I started the bot once again and this time i wrote something in the channel after 1 minute and the bot started recieving pings from quakenet, thats when i though "thats it? all i need is a activity and it will start reciving pings?
it was not that easy, it got 1 ping after 1 activity... after a while i wrote something else but the output didn't show since the bot had already lost connection and i was talking to a ghost.
http://pastebin.com/RF0DhMDp

So i figured "more activity maby?" so i wrote a message after 2 minutes, then after 4 minutes, both gave pings... then one after 10 minutes but by then it was a ghost again.
http://pastebin.com/Zbk98KMF

PS. used pastebin, was afraid i would bloat the post to much.

And this is as far as i'w come, quakenet will ping the bot after any type of activity in the channel giving it more time alive but as soon as silence strike the bot will die.

kieeps’s picture

i'w been experimenting a bit more and with $irc->setTransmitTimeout(1200); and $irc->setReceiveTimeout(1500); and got the timout to be delayed, but now i realise that it wont help anway.

Even though it takes it 10 minutes instead of 5 minutes to drop it will drop, i'w gotten alot more activity in the channel and that keeps the bot alive longer with the diffrense that it doesn't just drop, he drops and leavs a ghost while it's activity and just drops and reconnect when there is none.

This is durring activity

22:32 -- mode/#zhtp-stat [+o the_hatter] by eggelz
22:41 -- the_h849 [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] joins -> #zhtp-stat
22:41 -- mode/#zhtp-stat [+o the_h849] by eggelz
22:42 -- the_hatter [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] <- quit [Ping timeout]
22:42 -- the_h849 is now known as the_hatter
22:47 -- the_h415 [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] joins -> #zhtp-stat
22:47 -- mode/#zhtp-stat [+o the_h415] by eggelz
22:48 -- the_hatter [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] <- quit [Ping timeout]
22:52 -- the_h415 is now known as the_hatter
23:01 -- the_hatter [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] <- quit [Ping timeout]
23:20 -- the_hatter [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] joins -> #zhtp-stat
23:21 -- mode/#zhtp-stat [+o the_hatter] by eggelz

and this is while channel is idle

03:32 -- the_hatter [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] <- quit [Read error: Operation timed out]
03:33 -- the_hatter [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] joins -> #zhtp-stat
03:33 -- mode/#zhtp-stat [+o the_hatter] by eggelz
03:41 -- the_hatter [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] <- quit [Read error: Operation timed out]
03:41 -- the_hatter [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] joins -> #zhtp-stat
03:42 -- mode/#zhtp-stat [+o the_hatter] by eggelz
03:49 -- the_hatter [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] <- quit [Read error: Operation timed out]
03:49 -- the_hatter [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] joins -> #zhtp-stat
03:51 -- mode/#zhtp-stat [+o the_hatter] by eggelz
04:06 -- the_hatter [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] <- quit [Read error: Operation timed out]
04:07 -- the_hatter [~the_hatte@c-6c9ce255.017-43-6b736418.cust.bredbandsbolaget.se] joins -> #zhtp-stat

Starting to think that seeing how the bot is built it might not be cut out for quakenet, quakenet doesn't have a good pingpong system running, it comes and goes, the bot can be alive and functioning for a while 'cus it gets pings from the server that prevents it from dropping/ghosting but that stops after a while aswell.

Is it the SmartIRC backend that needs it to get pings/activity to prevent reconnections or is it code inside the bot? is it possible to turn it off? i know it fills a function but i'd prefer to have to start i manualy then to have it spam the channel with rejoins.

I'd really love to get this bot running smooth since it's REALLY usefull for uss when it announces new tickets and such.

kieeps’s picture

I get how this is a low prio issue but i figured i'd check in and see if there is any other kind of info that could be useful for you?

I did make a very poor workarround though, since i have eggdrops on several networks i switched the drupal bot to freenode since it works so much better there, joined him in a protected channel with an eggdrop and linked that bot with a quakenet bot through botnet and added a channel relay tcl script that relays everything the drupal bot say to the other bot on quakenet... so far i love this bot :)