Telegram -> IRC message relaying stops

[kengu2]

After running teleirc for some days there have now been two occasions where the messages from Telegram are not passed on to IRC but works all the time the other way round. There is no sign of those messages in the debug.

After restart the missing messages are relayed from the queue.

[FruitieX]

Very odd, I've been running mine for months now without problems. Which IRC network is this on, and can you confirm that you are running the latest version of teleirc (along with up to date libraries in node_modules)?

[kengu2]

Network is Freenode. Teleirc is the latest and for the last 3 days it has been running without problems. Libraries should also be up to date as it is pretty fresh install.

It might (but without any evidence) be related to either attachments or possibly reconnecting on IRC network.

[FruitieX]

Hey, I haven't been able to reproduce this problem unfortunately. Sorry about the delay also, I'm on a very busy schedule at the moment. I'd very much like to fix this, so if you have logs can you check if:

• The message " >> relaying to IRC: _____" is still printed to console when a message was supposed to be relayed to IRC.
• Has the IRC module raised any errors for some reason? (grep the logs for the string "IRC ERROR") Currently there's no auto-reconnect on error, but maybe there should be.

I'll have to do some more thorough tests with e.g. disconnecting my network connection and checking if teleirc continues working.

[kengu2]

To reproduce this problem seems a bit tricky. As there seems not to be any obvious reasons. Now when there is another channel added we found out that the relaying can stop on one channel but continue on the other.

There is no sign in the logs of the messages that are not relayed. So no log stating "relaying to IRC". And the error on IRC side. It is still on both channels and relaying in one direction on both channels.

This is what there is then on restart of teleirc. It relays the missing messages. Some lines are here multiple times but not shown on IRC. (id's of channels I obfuscated a bit)

$ teleirc


NOTE!
=====
id found for: Vaasa Hacklab : -4169179
id found for: Hacklab.fi : -10830927


11 Feb 15:00:52 - Sending irc NICK/USER
  >> relaying to IRC: <oh6gzt>: Ku ny sais aikaiseksi
11 Feb 15:00:53 - SEND: NICK vhtg
11 Feb 15:00:54 - SEND: USER bot 8 * :Telegram IRC Bot
  >> relaying to IRC: <oh6gzt>: Ku ny sais aikaiseksi
  >> relaying to IRC: <oh6gzt>: Ku ny sais aikaiseksi
  >> relaying to IRC: <oh6gzt>: Ku ny sais aikaiseksi
  >> relaying to IRC: <oh6gzt>: Ku ny sais aikaiseksi
11 Feb 15:01:02 - Unhandled message: { prefix: 'wolfe.freenode.net',
  server: 'wolfe.freenode.net',
  command: 'rpl_luserunknown',
  rawCommand: '253',
  commandType: 'reply',
  args: [ 'vhtg', '7', 'unknown connection(s)' ] }
11 Feb 15:01:02 - MODE: vhtg sets mode: +i
11 Feb 15:01:02 - SEND: JOIN #VaasaHacklab
11 Feb 15:01:03 - SEND: JOIN #hacklab.fi
  >> relaying to IRC: <oh6gzt>: Ku ny sais aikaiseksi
  >> relaying to IRC: <oh6gzt>: �
  >> relaying to IRC: <oh6gzt>: Sorville sähköä ja valoa. Sorvi itsessään odottaa jalkoja mutta jätän sen muille
  >> relaying to IRC: <oh6gzt>: Ping
11 Feb 15:01:05 - SEND: PRIVMSG #VaasaHacklab :<oh6gzt>: Ku ny sais aikaiseksi
  >> relaying to IRC: <oh6gzt>: (Photo, 1280x960) http://offshore.vaasa.hacklab.fi:9090/file_123.jpg
  >> relaying to IRC: <oh6gzt>: (Photo, 1280x960) http://offshore.vaasa.hacklab.fi:9090/file_124.jpg
11 Feb 15:01:06 - SEND: PRIVMSG #VaasaHacklab :<oh6gzt>: �
11 Feb 15:01:07 - SEND: PRIVMSG #VaasaHacklab :<oh6gzt>: Sorville sähköä ja valoa. Sorvi itsessään odottaa jalkoja mutta jätän sen muille
11 Feb 15:01:08 - SEND: PRIVMSG #VaasaHacklab :<oh6gzt>: Ping
11 Feb 15:01:09 - SEND: PRIVMSG #VaasaHacklab :<oh6gzt>: (Photo, 1280x960) http://offshore.vaasa.hacklab.fi:9090/file_123.jpg
11 Feb 15:01:10 - SEND: PRIVMSG #VaasaHacklab :<oh6gzt>: (Photo, 1280x960) http://offshore.vaasa.hacklab.fi:9090/file_124.jpg
11 Feb 15:01:11 - SEND: MODE #VaasaHacklab
11 Feb 15:01:12 - SEND: MODE #hacklab.fi

[FruitieX]

@kengu2 can you test the irc-git branch, which installs the node-irc module from latest master. Let me know if it works. If it fixes the issue, I'll release a hotfix version as soon as node-irc updates their npm module.

[kengu2]

I can try (or running at the moment) but as the problem is pretty random it might be difficult to figure out if the problem persists or if it is fixed.

Interesting thing to note is that when the bot is on two channels the relaying stopped on one but it continued on other a week ago.

[FruitieX]

That's odd for sure. Let's hope that the latest node-irc module fixes the problem, report back if you notice that it doesn't.

[kengu2]

During the night teleirc had some weird functionality. As there are other connections from the specific host to freenode without problems and teleirc had connections to different servers randomly I don't think the problem is with freenode as such.

Disconnecting from IRC every 4-5 minutes
Messaging telegram on every connect "topic for channel undefined"
Each IRC message seemed to be relayed twice to telegram

CyclingPingTimer 20: server silent for too long, let's send a PING
23 Feb 01:27:37 - SEND: PING 12394
23 Feb 01:27:48 - SEND: PONG asimov.freenode.net
CyclingPingTimer 20: server silent for too long, let's send a PING
23 Feb 01:28:03 - SEND: PING 12395
CyclingPingTimer 20: server silent for too long, let's send a PING
23 Feb 01:28:19 - SEND: PING 12396
CyclingPingTimer 20: server silent for too long, let's send a PING
23 Feb 01:28:35 - SEND: PING 12397
CyclingPingTimer 20: server silent for too long, let's send a PING
23 Feb 01:28:51 - SEND: PING 12398
CyclingPingTimer 20: server silent for too long, let's send a PING
23 Feb 01:29:07 - SEND: PING 12399
CyclingPingTimer 20: server silent for too long, let's send a PING
23 Feb 01:29:23 - SEND: PING 12400
CyclingPingTimer 20: server silent for too long, let's send a PING
23 Feb 01:29:39 - SEND: PING 12401
23 Feb 01:29:51 - QUIT: vhtg10!~bot@sa.hacklab.fi Ping timeout: 244 seconds
23 Feb 01:29:51 - Unhandled message: { command: 'ERROR',
  rawCommand: 'ERROR',
  commandType: 'normal',
  args: [ 'Closing Link: sa.hacklab.fi (Ping timeout: 244 seconds)' 
] }
23 Feb 01:29:51 - Connection got "end" event  
23 Feb 01:29:51 - Connection got "close" event
23 Feb 01:29:51 - Disconnected: reconnecting
23 Feb 01:29:51 - Waiting 2000ms before retrying
23 Feb 01:29:52 - QUIT: vhtg10!~bot@sa.hacklab.fi Ping timeout: 244 seconds
23 Feb 01:29:54 - Sending irc NICK/USER  
23 Feb 01:29:54 - SEND: NICK vhtg
23 Feb 01:29:55 - SEND: USER bot 8 * :Telegram IRC Bot
23 Feb 01:29:56 - SEND: NICK vhtg11
...

...
CyclingPingTimer 22: server silent for too long, let's send a PING
23 Feb 01:34:40 - SEND: PING 12416
  >> relaying to TG: <oh>: jaa :)
  >> relaying to TG: <oh>: jaa :)

(different timezone on server)

[FruitieX]

Ouch, something is seriously wrong there...

[kengu2]

I had to revert back to before "node-irc" version because of the connection flooding. Jumping on and off IRC network without reason and flooding IRC. And when connecting also stating the topic every time on telegram thus flooding Telegram.

[FruitieX]

sigh time to write our own irc module? :p

[ghost]

I just ran into this issue. resetting it wasn't doing anything.
ended up just disabling serve media option and it started working again.

[FruitieX]

That option should be unrelated to this problem @GeneralUnRest. I believe the problem lies in the IRC module. We're setting up the event listeners once (here), so I'm not sure how they can start firing multiple times unless that module is broken.

It is of course a possibility that the TG module is causing problems, but the problem @lagleki described supports the theory of the IRC module being broken since it connected to the IRC network multiple times (taking up several nicks).

I have one theory of what happened on your end @kengu2: maybe the connection between your server and the IRC network was down for an extended amount of time, causing lots of ping timeouts and reconnects in the IRC module. I'm trying to study how the module reacts to this situation, and to me it would seem that they never explicitly close a socket that was determined to have timed out? (here). They do manually trigger the 'close' event on the socket, but this AFAIK accomplishes nothing on node's side and they should also call .destroy() on the socket. It may be possible that the socket lingers around after their ping timeouts thus causing the problem.

This could explain why a message is relayed to IRC multiple times, but not really the other way around since it seems they really do remove the on 'data' event handler in either case. That is a little bit mysterious. Anyway, I wonder if it would help to add a self.conn.destroy() on this line.

[FruitieX]

This self.conn.destroy() patch has been applied to https://github.com/FruitieX/teleirc/tree/irc-git

If anyone wants to test...

Edit: don't waste your time on this. I've confirmed this issue still persists with that hack. Seems node-irc master branch suffers from this reconnect problem, it's not our fault. I'll open an issue with them, don't use the irc-git branch in the mean time.

You can follow the discussion here: martynsmith/node-irc#449

[jirwin]

@FruitieX Just wanted to let you know that I've pushed a patch that seems to fix this @ martynsmith/node-irc#452. It'd be great if you could give it a try as well so I can get it merged and finally publish the ping timeout support.

You were on the right track with self.conn.destroy(). The problem was because the code was emitting the close event on the socket directly instead of closing the connection and letting node emit the event itself.

Sorry for the trouble. Hope to get this fixed quickly.

[duck57]

I'm not sure if I should open a new issue for this or not, but I'm having a related but opposite problem. IRC messages for a specific channel aren't getting relayed to Telegram. In fact, there is nothing in the console output to show that the bot attempted to post to Telegram—it's like he bot has write access to the one channel but can't read from it.

However, this only is happening for one of the two links I made. On the other channel, it's working normally. It does not depend on which order I list the links in config.js, either. I'll play around with debug mode for a bit and let you know if I find anything else interesting.

[duck57]

It turns out that the IRC channel name is case-sensitive for reading, but the server I connected to is not case-sensitive, so it will forward messages to #CHANNEL to #channel.

[Mikaela]

It turns out that the IRC channel name is case-sensitive for reading, but the server I connected to is not case-sensitive, so it will forward messages to #CHANNEL to #channel.

This sounds like #36.

[duck57]

It seems to be exactly #36.

[jirwin]

@FruitieX Just letting you know that I've published node-irc 0.5.0 that has the fix for this in it.

[FruitieX]

Thank you very much for the note @jirwin, I will work towards a new hotfix release for next week when I'm finished with holidays. :)

[FruitieX]

Right, so this should be fixed now in the branch 045_rc. Let me know if this is not the case, otherwise we're releasing 0.4.5 by the end of next week!