shizmob/pydle

Bot dies when user joins channel and has modes set

logan2611 opened this issue · 10 comments

logan2611 commented

Hi, I was making a simple IRC bot and I noticed that sometimes the bot would seemingly randomly stop working. After some debugging, I eventually figured out that the bot stopped working whenever I joined the channel. I also noticed that on my private IRC server the bot would crash with the same error when NickServ notified the bot that its nickname wasn't registered.

Steps to reproduce:

  1. I used the simple IRC echo bot example code for this test, adjusting the values so that it joins my IRC server
  2. Bot joins channel
  3. User joins channel
  4. ChanServ sets modes +q and/or +o on user
    OR
  5. Use the simple echo IRC bot
  6. Join a server that sends a notification that your nick isn't registered

Error:

Task exception was never retrieved
future: <Task finished name='Task-2' coro=<BasicClient.handle_forever() done, defined at /mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/client.py:363> exception=AttributeError("'bool' object has no attribute 'replace'")>
Traceback (most recent call last):
  File "/mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/client.py", line 382, in handle_forever
    await self.on_data(data)
  File "/mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/client.py", line 391, in on_data
    message = self._parse_message()
  File "/mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/features/ircv3/tags.py", line 121, in _parse_message
    return TaggedMessage.parse(message + sep, encoding=self.encoding)
  File "/mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/features/ircv3/tags.py", line 70, in parse
    value = value.replace(escape, replacement)
AttributeError: 'bool' object has no attribute 'replace'
theunkn0wn1 commented

Attempted to reproduce,
using sample Echo example modified to point my IRC server.

$ cat example.py 
import pydle

# Simple echo bot.
class MyOwnBot(pydle.Client):
    async def on_connect(self):
         await self.join('#unkn0wndev')

    async def on_message(self, target, source, message):
         # don't respond to our own messages, as this leads to a positive feedback loop
         if source != self.nickname:
            await self.message(target, message)

client = MyOwnBot('MyBot', realname='My Bot')
client.run('localhost', tls=True, tls_verify=False)

using constraint of chanserv setting +q on user join.

Test setup: using IRC environment https://github.com/theunkn0wn1/unrealircd_docker
Configured #unkn0wndev to be owned by idented user unknown so +q is set by chanserv when that user connects.

Test run:

  1. launched example.py
  2. connected target user to server, idents, joins channel
  3. observe no crash
$ python example.py           
Unknown command: [irc.unknown.com] 396 ['MyBot', '161D248E.B897F01F.3F699B1A.IP', 'is now your displayed host']

* ChanServ sets mode +q on #unkn0wndev unknown
* ChanServ gives channel operator status to unknown
<unknown> pung
<MyBot> pung
<unknown> ping
<MyBot> ping
<unknown> pong
<MyBot> pong```

@logan2611 by chance can you point me at a server that would emit this nick not registered message?
Unable to reproduce without further information, can you please add this to the top of example.py and reproduce?

import logging
logging.basicConfig(level=logging.DEBUG)
theunkn0wn1 commented

Peering at code, looks like it has to do with IRCv3 tags not getting processed correctly.
https://github.com/Shizmob/pydle/blob/develop/pydle/features/ircv3/tags.py#L65 in specific is most suspect.
I would still appreciate some debug logs showing the message pydle is having a hickup over to verify.

logan2611 commented

Here are those debug logs, starting after the MOTD. I can only seem to reliablely recreate this issue on my own IRC server. I am using Inspircd and Anope for services by the way.

DEBUG:MyOwnBot:(servername):>> JOIN #logan2611

DEBUG:MyOwnBot:(servername):<< :irc.(domain) NOTICE MyBot :*** You are connected to irc.(domain) using TLS (SSL) cipher 'TLS1.3-ECDHE-RSA-AES-256-GCM-AEAD'
DEBUG:MyOwnBot:(servername):<< :MyBot!mybot@(ip) JOIN #logan2611 * :My Bot
DEBUG:MyOwnBot:(servername):>> MODE #logan2611

DEBUG:MyOwnBot:(servername):>> WHO #logan2611 %tnurha,542

DEBUG:MyOwnBot:(servername):<< :irc.(domain) 332 MyBot #logan2611 :(channel description)
DEBUG:MyOwnBot:(servername):<< :irc.(domain) 333 MyBot #logan2611 logan2611 :1602201541
DEBUG:MyOwnBot:(servername):<< :irc.(domain) 353 MyBot = #logan2611 :&@ChanServ!services@services.(domain) MyBot!mybot@(ip)
DEBUG:MyOwnBot:(servername):<< :irc.(domain) 366 MyBot #logan2611 :End of /NAMES list.
DEBUG:MyOwnBot:(servername):<< :irc.(domain) 324 MyBot #logan2611 :+nrt
DEBUG:MyOwnBot:(servername):<< :irc.(domain) 329 MyBot #logan2611 :1601968270
DEBUG:MyOwnBot:(servername):<< :irc.(domain) 354 MyBot 542 services services.(domain) ChanServ 0 :Channel Registration Service
DEBUG:MyOwnBot:(servername):<< :irc.(domain) 354 MyBot 542 mybot (ip) MyBot 0 :My Bot
DEBUG:MyOwnBot:(servername):<< :irc.(domain) 315 MyBot #logan2611 :End of /WHO list.
DEBUG:MyOwnBot:(servername):<< @account=logan2611 :logan26111!logan2611@(ip) JOIN #logan2611 logan2611 :realname
ERROR:asyncio:Task exception was never retrieved
future: <Task finished name='Task-2' coro=<BasicClient.handle_forever() done, defined at /mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/client.py:363> exception=AttributeError("'bool' object has no attribute 'replace'")>
Traceback (most recent call last):
  File "/mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/client.py", line 382, in handle_forever
    await self.on_data(data)
  File "/mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/client.py", line 391, in on_data
    message = self._parse_message()
  File "/mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/features/ircv3/tags.py", line 121, in _parse_message
    return TaggedMessage.parse(message + sep, encoding=self.encoding)
  File "/mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/features/ircv3/tags.py", line 70, in parse
    value = value.replace(escape, replacement)
AttributeError: 'bool' object has no attribute 'replace'

Looks like it is be getting hung up on :ChanServ!services@services.(domain) MODE #logan2611 +qo logan2611 :logan2611 since when I join another channel I get DEBUG:MyOwnBot:(servername):<< @account=logan2611 :logan26111!logan2611@(ip) JOIN #lolfunnymeme logan2611 :realname without an error.

ZeroKnight commented

Peering at code, looks like it has to do with IRCv3 tags not getting processed correctly.
https://github.com/Shizmob/pydle/blob/develop/pydle/features/ircv3/tags.py#L65 in specific is most suspect.

After studying that bit for a moment, I understand that it's handling tags that have no value. Per current IRCv3 docs, tag values are optional, though it is not specified how valueless tags should be interpreted, likely to allow for flexibility in tag semantics. Regardless, a boolean True value is a logical interpretation of a valueless tag, as in the rose example here. As far as I'm concerned, that block is mostly fine1 in and of itself.

[EDITED]: Forgot to include the second loop
The problem is in the next two blocks:
https://github.com/Shizmob/pydle/blob/514ad98f5b1640a589e7b5376a2b9f5c47bde2b5/pydle/features/ircv3/tags.py#L69-L76
Here, value is assumed to always be a string, even though we know it can sometimes be True. These two loops should only run when value is a string, but since it isn't, we get the described AttributeError.

Based on the exception, we can deduce that the problematic message includes a valueless tag. We don't know what the message payload looks like since the exception is thrown in _parse_message just before on_raw has a chance to log the message. However, based on the fault above, the specific tag is irrelevant to the fact that valueless tags are handled incorrectly. Regardless, knowing could provide a useful basis for a regression test, so it should be easy enough to obtain with a simple on_data extension. @logan2611 would just have to add the following:

async def on_data(self, data):
	print(f'**!** {data=}')
    await super().on_data(data)

Then the offending message should be spat out just before the exception.

1: It doesn't correctly handle empty tag values. Per spec:

Implementations MUST interpret empty tag values (e.g. foo=) as equivalent to missing tag values (e.g. foo). Specifications MUST NOT differentiate meaning between tags with empty and missing values.

As that block is currently written, an empty tag would cause value to be ''. This should be addressed in another issue.

ZeroKnight commented

I can reproduce this exception on the develop branch by injecting a fake, valueless tag into the data before it gets passed to _parse_message. Here is the minimal test case I used:

import pydle

class Bot(pydle.Client):
    async def on_connect(self):
        print('connected')

    async def on_data(self, data):
        if b'PRIVMSG' in data and b'005' not in data:
            # Inject tags into message
            data = b'@empty=;missing ' + data
        print(data)
        await super().on_data(data)

bot = Bot('pydle_test_bot')
bot.run('irc.freenode.net')

The trigger is a (rather lazily detected) PRIVMSG from any source. Conveniently, Freenode's frigg bot will send a CTCP VERSION on connection, which automates things a bit. I included both an empty tag and a valueless tag for the sake of completeness, but as mentioned the exception is tied to the latter. Here is the output, if anyone is interested:

[snip] connection registration and MOTD [/snip]
connected
b':pydle_test_bot_ MODE pydle_test_bot_ :+i\r\n'
b':freenode-connect!frigg@freenode/utility-bot/frigg NOTICE pydle_test_bot_ :Welcome to freenode. To protect the network all new connections will be scanned for vulnerabilities. This will not harm your computer, and vulnerable hosts will be notified.\r\n'
b'@empty=;missing :freenode-connect!frigg@freenode/utility-bot/frigg PRIVMSG pydle_test_bot_ :\x01VERSION\x01\r\n'
Task exception was never retrieved
future: <Task finished name='Task-2' coro=<BasicClient.handle_forever() done, defined at /home/zeroknight/repo/pydle/pydle/client.py:363> exception=AttributeError("'bool' object has no attribute 'replace'")>
Traceback (most recent call last):
  File "/home/zeroknight/repo/pydle/pydle/client.py", line 382, in handle_forever
    await self.on_data(data)
  File "./testbot.py", line 15, in on_data
    await super().on_data(data)
  File "/home/zeroknight/repo/pydle/pydle/client.py", line 391, in on_data
    message = self._parse_message()
  File "/home/zeroknight/repo/pydle/pydle/features/ircv3/tags.py", line 121, in _parse_message
    return TaggedMessage.parse(message + sep, encoding=self.encoding)
  File "/home/zeroknight/repo/pydle/pydle/features/ircv3/tags.py", line 70, in parse
    value = value.replace(escape, replacement)
AttributeError: 'bool' object has no attribute 'replace'
theunkn0wn1 commented

Thanks, can reproduce with your test case there @ZeroKnight .

When I pointed out the tag being set to True, I very much was just thinking about the datatype mismatch.

In the case where a tag doesn't have a value, Pydle appears to use them as flags and sets them to True.

You do appear to be correct in that pydle does not normalize empty to missing, so we have two issues here.

committing the missing tag as-is without doing the post-processing escape sequence processing as we do for full tags avoids the exception in the OP but doesn't normalize the tags as per the spec.
Methinks if we checked if the value after the tag is an empty string we could use the same logic for empty= as missing

theunkn0wn1 commented

there appears to be an existing test for this feature that can be extended, can reproduce with existing test + new test case.

        (
                rb"@empty=;missing :unknown!orion@161D248E.B897F01F.3F699B1A.IP PRIVMSG #unkn0wndev :ping",
                {"empty": True, "missing": True}
        ),
  • 👍1
ZeroKnight commented

To get the ball rolling a bit, I started a pull request that should fix this issue. Using my same test case with this change, pydle throws no exception. I enabled contributor pushing, in case you'd like to add a commit for that new test case you mentioned.

#149

  • 👍1
logan2611 commented

Although it looks like a solution has already been mentioned, I'll still paste my logs to be sure, and also test the PR.

**!** data=b'@account=logan2611 :logan2611!logan2611@(ip) JOIN #logan2611 logan2611 :realname\r\n'
DEBUG:MyOwnBot:(servername):<< @account=logan2611 :logan2611!logan2611@(ip) JOIN #logan2611 logan2611 :realname
**!** data=b'@inspircd.org/service;inspircd.org/bot :ChanServ!services@services.(domain) MODE #logan2611 +qo logan2611 :logan2611\r\n'
ERROR:asyncio:Task exception was never retrieved
future: <Task finished name='Task-2' coro=<BasicClient.handle_forever() done, defined at /mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/client.py:363> exception=AttributeError("'bool' object has no attribute 'replace'")>
Traceback (most recent call last):
  File "/mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/client.py", line 382, in handle_forever
    await self.on_data(data)
  File "example.py", line 13, in on_data
    await super().on_data(data)
  File "/mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/client.py", line 391, in on_data
    message = self._parse_message()
  File "/mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/features/ircv3/tags.py", line 121, in _parse_message
    return TaggedMessage.parse(message + sep, encoding=self.encoding)
  File "/mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/features/ircv3/tags.py", line 70, in parse
    value = value.replace(escape, replacement)
AttributeError: 'bool' object has no attribute 'replace'
^CTraceback (most recent call last):
  File "example.py", line 21, in <module>
    client.run('irc.(domain)', tls=True, tls_verify=False)
  File "/mnt/hdd/Documents/ExampleBot/lib/python3.8/site-packages/pydle/client.py", line 108, in run
    self.eventloop.run_forever()
  File "/usr/lib/python3.8/asyncio/base_events.py", line 570, in run_forever
    self._run_once()
  File "/usr/lib/python3.8/asyncio/base_events.py", line 1823, in _run_once
    event_list = self._selector.select(timeout)
  File "/usr/lib/python3.8/selectors.py", line 468, in select
    fd_event_list = self._selector.poll(timeout, max_ev)
KeyboardInterrupt
ZeroKnight commented 
data=b'@inspircd.org/service;inspircd.org/bot :ChanServ!services@services.(domain) MODE #logan2611 +qo logan2611 :logan2611\r\n'

Ah, as expected, two valueless tags. Thanks for getting back, @logan2611!