Willie does not connect on versions > 4.6.0

[RustyBower]

Tried connecting with 4.6.1, 4.6.2, and 5.0.0-beta.

Same configuration file, running willie.py out of the tar.gz directory.

Also tried generating a new config with each version, and disabling all the addons.

Working (4.6.0): Registered 57 modules, 4 modules failed to load

Connecting to irc.xxxx.com:6697... Connected.

Not Working (4.6.1+): Registered 57 modules, 4 modules failed to load

Connecting to irc.xxxx.com:6697... Connected.

But it just sits there.

A tcpdump shows that traffic is happening, but the bot doesn't join the channel, or join the server (since I have oper and I can see connected clients)

[embolalia]

Can you post your raw.log or your config? What version of Python are you using? When you say 5.0, what commit are you on?

[RustyBower]

(For 5.x)

1419356201.88 NICK BotSaget 1419356201.88 USER willie +iw BotSaget :Willie Embosbot, http://willie.dftba.net 1419356201.88 CAP LS <<1419356201.95 :irc.xxxirc.com NOTICE AUTH :* Looking up your hostname... <<1419356201.96 :irc.xxxirc.com NOTICE AUTH :* Found your hostname <<1419356202.03 PING :FD96ADA8 1419356202.03 PONG FD96ADA8 <<1419356202.1 :irc.xxxirc.com CAP BotSaget LS :account-notify away-notify multi-prefix tls userhost-in-names <<1419356239.52 ERROR :Closing Link: BotSaget[1.2.3.4](Ping timeout: 38 seconds)

(For 4.6.2) raw.log

1419356310.96 QUIT :KeyboardInterrupt 1419356324.85 CAP LS 1419356324.85 NICK BotSaget 1419356324.85 USER willie +iw BotSaget :Willie Embosbot, http://willie.dftba.net <<1419356324.91 :irc.xxxirc.com NOTICE AUTH :* Looking up your hostname... <<1419356324.92 :irc.xxxirc.com NOTICE AUTH :* Found your hostname (cached) <<1419356324.98 :irc.xxxirc.com CAP * LS :account-notify away-notify multi-prefix tls userhost-in-names <<1419356325.09 PING :AB5860C6 1419356325.09 PONG AB5860C6 <<1419356361.86 ERROR :Closing Link: BotSaget[1.2.3.4](Ping timeout: 37 seconds)

and from the program itself

Connecting to irc.xxxirc.com:6697... Connected. /opt/willie-4.6.2/willie/tools.py:282: UserWarning: debugwill be removed in Willie 5.0. Please see http://willie.dftba.net/willie_5.html for more info. warnings.warn(thing + 'will be removed in Willie 5.0. Please see ' [irc.py] Closing Link: BotSaget[1.2.3.4](Ping timeout: 37 seconds) Calling shutdown for 4 modules. calling youtube.shutdown calling github.shutdown calling bugzilla.shutdown Error calling shutdown method for module bugzilla:None calling reddit.shutdown Closed! Warning: Disconnected. Reconnecting in 20 seconds...

(For 5.x) ubuntu@xxx:/opt/willie$ git rev-parse HEAD 61d7a137feb873460f4158283034b4d8ae322e3c

ubuntu@xxx:/opt/willie$ python -V Python 2.7.3

[ghost]

This error isn't unique. Latest repo clone:

1419728930.38 NICK lurkbot 1419728930.38 USER willie +iw lurkbot :Willie Embosbot, http://willie.dftba.net 1419728930.38 CAP LS <<1419728930.48 :irc.lurkmore.com NOTICE AUTH :* Looking up your hostname... <<1419728930.48 :irc.lurkmore.com NOTICE AUTH :* Found your hostname (cached) <<1419728930.59 PING :C06B0B6 1419728930.59 PONG C06B0B6 <<1419728930.69 :irc.lurkmore.com CAP lurkbot LS :account-notify away-notify multi-prefix tls userhost-in-names <<1419728965.22 ERROR :Closing Link: lurkbot[62.210.140.124](Ping timeout: 35 seconds) 1419728985.51 NICK lurkbot 1419728985.51 USER willie +iw lurkbot :Willie Embosbot, http://willie.dftba.net 1419728985.51 CAP LS <<1419728985.61 :irc.lurkmore.com NOTICE AUTH :* Looking up your hostname... <<1419728985.61 :irc.lurkmore.com NOTICE AUTH :* Found your hostname (cached) <<1419728986.61 PING :E01B10D1 1419728986.61 PONG E01B10D1 <<1419728986.61 :irc.lurkmore.com CAP lurkbot LS :account-notify away-notify multi-prefix tls userhost-in-names

[subterfugium]

Same here when connecting willie to ZNC 1.5 bouncer.

>>1419799960.99 CAP LS
>>1419799960.99 PASS **************************
>>1419799960.99 NICK hevosjeera
>>1419799960.99 USER hevosjeera +iw hevosjeera :hevosjeera
<<1419799960.99 :irc.znc.in CAP unknown-nick LS :userhost-in-names multi-prefix znc.in/server-time-iso znc.in/batch znc.in/self-message

Timeout after few minutes

>>1419800081.06 PING myhost.com
<<1419800081.42 ERROR :Closing link [Timeout]

Willie output

Welcome to Willie. Loading modules...

Registered 47 modules,
0 modules failed to load

Connecting to myhost.com:7001...
Connected.
[irc.pyc] Closing link [Timeout]
Calling shutdown for 4 modules.
calling reddit.shutdown
calling youtube.shutdown
calling github.shutdown
calling bugzilla.shutdown
Error calling shutdown method for module bugzilla:None
Closed!
Warning: Disconnected. Reconnecting in 20 seconds...

[elad661]

@subterfugium More recent versions of willie will send CAP LS after NICK and USER, please try with an up-to-date version and see if it helps?

@ (everyone, basically) can someone provide an example of a network which is affected by the issue that I can connect to for testing? the latest git master works both on freenode and on our network.

[ghost]

As my log shows, irc.lurkmore.com.

Also, you're right, it will connect to freenode without any issues.

[RustyBower]

irc.129irc.com (6667 // 6697 ssl)

On Tue, Dec 30, 2014 at 2:59 PM, blixnood notifications@github.com wrote:

As my log shows, irc.lurkmore.com.

— Reply to this email directly or view it on GitHub https://github.com/embolalia/willie/issues/695#issuecomment-68408219.

[RustyBower]

Just pulled the newest git version, still can't connect.

[elad661]

@blixnood I will not connect to an IRC network affiliated with 4chan. In fact, I think willie not working with such network is a good thing. 4chan is a horrible place.

@RustyBower thanks, I'll check this one later today.

[tyrope]

@blixnood I removed your comment as I found it offensive and it didn't contribute to the conversation.

[ghost]

Elad's comment is offensive and doesn't contribute to the conversation. His comment is still the dumbest thing I've read all day. It's fine, though, because the email notifications can't be removed.

[embolalia]

@blixnood, calling something someone said dumb is entirely unproductive. Moreover, @elad661 is a volunteer, as is everyone else here. While we want to provide good software, none of us is under any obligation to ensure it works in any specific situation. If @elad661 doesn't want to test against a specific network, that is entirely his decision.

To be clear, optimally this bot will connect to any server which follows the appropriate specifications. There are any number of reasons why some of the volunteers for this project might not be able to or want to connect to some of them. The best thing to do when this happens is to give us as much information as you can about the server in question - like, for example, what version of what daemon it's running. :+1: to @subterfugium for providing that.

I'm unlocking discussion on this. I trust that it will be confined to the technical matters at hand.

[elad661]

Fix it yourself, I'm not going to waste my time on this issue.

[Khabi]

To the original issue @RustyBower I was able to successfully connect with both the 4.6 branch and the master branch from git. However I have an idea of what is actually going on.

If I get a copy of willie and run it from the install directory it does not work and presents the issues that people are seeing. If you actually do the install process "python setup.py install" and run willie from your path, it works correctly. So I would say to do an actual install and try again.

I believe this will fix the issue with @subterfugium as well.

[RustyBower]

Unfortunately I am still getting the same issue (with git branch).

ubuntu@ip-10-1-2-3:/opt/willie$ willie

Welcome to Willie. Loading modules...

Error in safety setup procedure: ConfigurationError: Safety module not configured (modules/safety.py:55) Setting up CalcBucket... CalcBucket test item: [{'item_value': u'http://i.imgur.com/0L5c5e6.jpg', 'item_key': u'Athehomedepot', 'nick': u'chugdiesel'}] Done setting up CalcBucket! Error in karma setup procedure: 'WillieDB' object has no attribute 'karma' (../../../../../../home/ubuntu/.willie/modules/karma.py:71) Setting up Bucket... Done setting up Bucket!

Registered 60 modules, 2 modules failed to load

Connecting to irc.129irc.com:6697... Connected. /usr/local/lib/python2.7/dist-packages/willie/tools.py:282: UserWarning: debugwill be removed in Willie 5.0. Please see http://willie.dftba.net/willie_5.html for more info. warnings.warn(thing + 'will be removed in Willie 5.0. Please see ' [irc.pyc] Closing Link: BotSaget[1.2.3.4](Ping timeout: 35 seconds) Calling shutdown for 4 modules. calling reddit.shutdown calling youtube.shutdown calling bugzilla.shutdown Error calling shutdown method for module bugzilla:None calling github.shutdown Closed! Warning: Disconnected. Reconnecting in 20 seconds...

From raw.log:

1420403551.2 NICK BotSaget 1420403551.2 USER willie +iw BotSaget :Willie Embosbot, http://willie.dftba.net 1420403551.2 CAP LS <<1420403551.28 :ec2east.129irc.com NOTICE AUTH :* Looking up your hostname... <<1420403551.28 :ec2east.129irc.com NOTICE AUTH :* Found your hostname (cached) <<1420403551.36 PING :20E7964D 1420403551.36 PONG 20E7964D <<1420403551.43 :ec2east.129irc.com CAP BotSaget LS :account-notify away-notify multi-prefix tls userhost-in-names <<1420403586.37 ERROR :Closing Link: BotSaget[54.214.137.71](Ping timeout: 35 seconds)

[RustyBower]

Looks like the issue comes from this:

https://github.com/embolalia/willie/blob/master/willie/irc.py#L300

Commenting out that line fixes things.

[embolalia]

I had figured it was related to CAP LS (we can't just remove that as a complete solution, though, since that would break all sorts of IRCv3 stuff). The odd thing is, irc.irc129.com (or at least ec2east.129irc.com) is running Unreal 3.2.10.1. ftl.dftba.net (and I think the rest of irc.dftba.net) is Unreal 3.2.9. Still doesn't explain the ZNC problem, but I might be able to look into the difference in the Unreal versions to find the cause.

EDIT: Unreal fails at semver. 3.2.10 adds new major functionality, namely support for CAP. Obviously there's something specific the way it does it vs. how Freenode does it which needs to be looked into.

[RustyBower]

Ah. I'll get those versions sync'd up and I'll test again

[embolalia]

Looks like we weren't waiting quite long enough to send that; putting it after connection registration seems to work on newer Unreals. @RustyBower, should be fixed for you. @subterfugium, can you confirm this works for you on ZNC?

[RustyBower]

Seems like things are good now, at least for me (other people might be having issues, so not gonna close this out)

[subterfugium]

@embolalia @elad661 @Khabi The connection to ZNC with today's master branch does work indeed. Thank you :)

ZNC configured with DV cert and

SSLCiphers = AES256+EECDH:AES256+EDH:!aNULL
SSLProtocols = TLSv1.1 TLSv1.2
IPv4 = true
IPv6 = false
Port = xxxxx
SSL = true

[tyrope]

Apparently this is still an issue on EsperNET

[1809.22] <flashcactus> 5.0 flat-out refuses to connect properly.
[1809.39] <flashcactus> I think I posted something the issue.
[1809.47] <flashcactus> *regarding the
[1809.49] <@Tyrope> That issue is fixed iirc.
[1810.02] <@Tyrope> Assuming you mean this one
[1810.04] <@Tyrope> .findbug 695
[1810.06] <Willie> Tyrope: [#695]title: Willie does not connect on versions > 4.6.0 | Tried connecting with 4.6.1, 4.6.2, and 5.0.0-beta....
[1810.07] <Willie> https://github.com/embolalia/willie/issues/695
[1810.15] <flashcactus> No, it just stalls a bit farther.
[1810.57] <@Tyrope> Which network is this?
[1811.11] <flashcactus> It doesn't get disconnected for not replying to the first ping, but it doesn't proceed to join the channels either.
[1811.16] <flashcactus> irc.esper.net

[flashcactus]

Relevant log for willie at commit 37cbda4:

>>1420650355.4041085    NICK Kountdown
>>1420650355.4272435    USER kountdown +iw Kountdown :Kountdown Willievich Cactusoff, http://github.com/flashcactus/kountdown/
>>1420650355.4300363    CAP LS
<<1420650355.5431767    :calamity.esper.net NOTICE * :*** Looking up your hostname...
<<1420650355.658895     :calamity.esper.net NOTICE * :*** Checking Ident
<<1420650355.6597586    :calamity.esper.net NOTICE * :*** No Ident response
<<1420650355.8040738    :calamity.esper.net NOTICE * :*** Couldn't look up your hostname
<<1420650355.919851     PING :00D6D190
>>1420650355.9200718    PONG 00D6D190
<<1420650355.9208632    :calamity.esper.net CAP Kountdown LS :account-notify away-notify extended-join multi-prefix sasl tls
<<1420650409.6176783    ERROR :Closing Link: 2a00:ab00:10b:46:182:30:120:0 (Connection timed out)

[embolalia]

Could not reproduce on irc.esper.net or calamity.esper.net at 16a4fb64e7f377016de41d44c5882b56edd432d0. Is this still happening?

[embolalia]

It seems this change breaks SASL auth, since AUTHENTICATE has to happen before connection registration. This will need more investigation.

[embolalia]

@Khabi I believe this is related to your PR #692. You mentioned being able to replicate it on multiple servers; could you get me a list so I can verify?

[Khabi]

@embolalia one was freenode itself, and the other was a personal IRC server running ircd-hybrid 7.2.3 (I can give you the details on it privately if you want, I don't want to plaster it on the web).

I did a bit more testing afterwards, and I think it was related to a end irc server taking to long to get a ident response. The network I was on I suspect was just letting the request timeout instead of rejecting it. Equiv of doing "iptables -A INPUT -i $IFACE -p tcp --dport 113 -j DROP" instead of "iptables -A INPUT -i $IFACE -p tcp --dport 113 -j REJECT"

I have a bit of spare time today, I'll see if I can replicate it.

[elad661]

I didn't know IRC networks that used ident still exist, it is pretty much useless in the age where most actual users are behind some sort of NAT or CGNAT.

I am 100% sure freenode doesn't require ident, because my firewall is not configured to allow this port in and I don't run an ident daemon, yet I connect to freenode with no problems.

[Khabi]

I've tried today and I've been unable to replicate it from my home machine, so I'm not really sure what to make of it. My initial assumption (it was a quick one, I didn't do any in depth troubleshooting) was that ident was taking to long to timeout (even if not required) and on the server side it was possibly running into some kind of session timeout or something. I did some iptables trickery to see if I could reproduce it, but got nowhere.

The odd part about all of this, is obviously on some networks moving the CAP later on works see @subterfugium @RustyBower and my test cases on pull https://github.com/embolalia/willie/pull/692. Of course as @embolalia pointed out that breaks sasl connections now.

The best I can come up with without reading all of the IRC RFC is that maybe it has something to do with IPV6 (I see that in a few of the logs here) and CAP. Honestly, that seems silly.

If I get some time tomorrow I'll try to replicate the issue again from the same network I originally had the issues on. Maybe I'll do some tcpdumps and see if anything else pops out.

[lkarsten]

I ran into a similar issue today. Latest git 2a93da against Espernet.

Connect appeared to work fine, the bot joins the (single) configure channel, but it otherwise unresponsive. After a while it reconnects after logging a timeout on the console.

IRC server was availo.esper.net.

I got this working through hard-coding the ipv4 address of the irc server, forcing it to connect over IPv4.

[embolalia]

@lkarsten, the failures here happen before JOIN is sent out at all, so if it's joining a channel you have a different issue. Please file a separate bug, including appropriate logs of your error. The issue in this bug appears to have been resolved, so I'm closing it.