KeyError: u'*' bot.py _on_namreply traceback

[jaraco]

KeyError: u'*' bot.py _on_namreply traceback

[jaraco]

Hi Brian. Sorry to hear you're having trouble, and sorry for the delayed reply.

Can you please run the client with debug logging enabled, for example by invoking this command prior to starting the client:

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

That should provide some better feedback about the commands being received and thus what causes the failure.

If you follow the traceback, you'll see that the failure occurs in irc.bot:173 where apparently the second argument (arguments[1]), which is supposed to be the channel, is actually the type. Perhaps something has changed about the parsing that has caused this to fail, and the debug logs should illuminate the problem.

Thanks for using irclib, and I look forward to getting this issue resolved for you.

Regards,
Jason

---

Original comment by: Jason R. Coombs

[jaraco]

Hi Jason. Thanks for the reply. My client code does setup a logger at the DEBUG level, but curiously I only see my application's logging statements, not anything from the irc library. Maybe you can see what I am missing:

I run my client as a daemon, and on that thread I do a

#!python

logging.config.fileConfig(self.config)

And I have this in a config file:

[loggers]
keys = root

[handlers]
keys = hand01

[formatters]
keys = form01

[logger_root]
level = DEBUG
handlers = hand01

[handler_hand01]
class = FileHandler
level = NOTSET
formatter = form01
args = ('/path/to/my/log/file.log', 'w')

[formatter_form01]
format = %(asctime)s %(levelname)s %(message)s
datefmt =

Again, the above seems to setup the log file correctly, but I only see logging from my code.

Another problem is this happens very infrequently. I think it has happened only 1 other time since I reported it.

I forgot to mention I am using ngircd for the server.

Thanks!

---

Original comment by: Brian Neal

[jaraco]

Oh, perhaps I need to setup the logger before I import anything from irc?

---

Original comment by: Brian Neal

[jaraco]

I should think that you could set it up at any time. Unfortunately, I'm not familiar with the config file format, so I'm not quite sure what to expect from that config.

I should also admit that I haven't tried the debug logging recently, so I should do that and confirm it actually works as i said.

---

Original comment by: Jason R. Coombs

[jaraco]

I'm using a 3rd party daemon package to daemonize the thing, and I remember having problems getting the logging working unless I called logging.config.fileConfig() from the new process. I'll try to see if I can run it without all the daemon stuff and see if I see logging output from irc.

---

Original comment by: Brian Neal

[jaraco]

Ok, I got it. Nevermind all that daemon stuff. I had to change my call to this:

#!python

logging.config.fileConfig(self.config, disable_existing_loggers=False)

Now I'll report back in a few weeks when it finally dies. :) Thanks Jason.

---

Original comment by: Brian Neal

[jaraco]

I've confirmed that the debug logging does work as expected with the simple 'irccat.py', which I just updated in e16da8e2a8 to support setting the debug logging.

---

Original comment by: Jason R. Coombs

[jaraco]

Welcome! Good luck.

---

Original comment by: Jason R. Coombs

[jaraco]

Ok I got a traceback with some debug. I'm not real sure how to read some of the IRC debug so I'll start from just a bit before the traceback. If you need me to go back further let me know. I also obfuscated a few path & server names:

#!python

2013-07-15 07:39:40,824 DEBUG _dispatcher: all_raw_messages
2013-07-15 07:39:40,825 DEBUG command: namreply, source: irc.example.com, target: bot, arguments: [u'=', u'#MyChannel', u'Frus bot']
2013-07-15 07:39:40,825 DEBUG _dispatcher: namreply
2013-07-15 07:39:40,825 DEBUG FROM SERVER: :irc.example.com 366 bot * :End of NAMES list
2013-07-15 07:39:40,825 DEBUG _dispatcher: all_raw_messages
2013-07-15 07:39:40,825 DEBUG command: endofnames, source: irc.example.com, target: bot, arguments: [u'*', u'End of NAMES list']
2013-07-15 07:39:40,826 DEBUG _dispatcher: endofnames
2013-07-15 07:41:41,707 DEBUG FROM SERVER: PING :irc.example.com
2013-07-15 07:41:41,707 DEBUG _dispatcher: all_raw_messages
2013-07-15 07:41:41,707 DEBUG command: ping, source: None, target: irc.example.com, arguments: [u'irc.example.com']
2013-07-15 07:41:41,707 DEBUG TO SERVER: PONG irc.example.com
2013-07-15 07:41:41,707 DEBUG _dispatcher: ping
2013-07-15 07:41:41,708 DEBUG TO SERVER: NAMES
2013-07-15 07:41:41,747 DEBUG FROM SERVER: :irc.example.com 353 bot = #MyChannel :Frus bot
2013-07-15 07:41:41,747 DEBUG _dispatcher: all_raw_messages
2013-07-15 07:41:41,747 DEBUG command: namreply, source: irc.example.com, target: bot, arguments: [u'=', u'#MyChannel', u'Frus bot']
2013-07-15 07:41:41,748 DEBUG _dispatcher: namreply
2013-07-15 07:41:41,748 DEBUG FROM SERVER: :irc.example.com 353 bot * * :Furs
2013-07-15 07:41:41,748 DEBUG _dispatcher: all_raw_messages
2013-07-15 07:41:41,748 DEBUG command: namreply, source: irc.example.com, target: bot, arguments: [u'*', u'*', u'Furs']
2013-07-15 07:41:41,748 ERROR Exception on bot.start():
Traceback (most recent call last):
  File "/svr/irc/mybot/mybot/mybotlib/main.py", line 54, in run
    self.bot.start()
  File "/svr/irc/mybot/mybot/mybotlib/bot.py", line 28, in start
    super(Bot, self).start()
  File "/svr/irc/mybot/local/lib/python2.7/site-packages/irc/bot.py", line 260, in start
    super(SingleServerIRCBot, self).start()
  File "/svr/irc/mybot/local/lib/python2.7/site-packages/irc/client.py", line 1212, in start
    self.ircobj.process_forever()
  File "/svr/irc/mybot/local/lib/python2.7/site-packages/irc/client.py", line 264, in process_forever
    self.process_once(timeout)
  File "/svr/irc/mybot/local/lib/python2.7/site-packages/irc/client.py", line 245, in process_once
    self.process_data(i)
  File "/svr/irc/mybot/local/lib/python2.7/site-packages/irc/client.py", line 210, in process_data
    c.process_data()
  File "/svr/irc/mybot/local/lib/python2.7/site-packages/irc/client.py", line 643, in process_data
    self._handle_event(Event(command, NickMask(prefix), target, arguments))
  File "/svr/irc/mybot/local/lib/python2.7/site-packages/irc/client.py", line 647, in _handle_event
    self.irclibobj._handle_event(self, event)
  File "/svr/irc/mybot/local/lib/python2.7/site-packages/irc/client.py", line 384, in _handle_event
    result = handler.callback(connection, event)
  File "/svr/irc/mybot/local/lib/python2.7/site-packages/irc/bot.py", line 173, in _on_namreply
    self.channels[ch].add_user(nick)
  File "/svr/irc/mybot/local/lib/python2.7/site-packages/irc/dict.py", line 30, in __getitem__
    return super(KeyTransformingDict, self).__getitem__(key)
KeyError: u'*'
2013-07-15 07:41:41,750 INFO mybot ending
2013-07-15 07:41:41,750 DEBUG leaving main

Let me know how I can help. I can try to work up a patch if you have any hints. Thanks!

---

Original comment by: Brian Neal

[jaraco]

So that's very interesting - the server is transmitting

353 bot * * :Frus

That command is specified on page 47 in this RFC 2812. It indicates that the first argument should be '*', '=', or '@', but the second argument should be the channel.

Aha! Now reading this section of the RFC, I see that

At the end of this list, a list of users who are visible
but either not on any channel or not on a visible channel
are listed as being on `channel' "*".

But when IRC gets a channel '*', it expects it to show up in the channel list and chokes when it isn't. The bot should probably for now just ignore this value in on_namreply.

---

Original comment by: Jason R. Coombs

[jaraco]

Catch error when nick is not in any visible channel. Fixes #22

→ <>

---

Original comment by: Jason R. Coombs

[jaraco]

Fix released as 8.3.2. Please report back if this doesn't fix the issue.

---

Original comment by: Jason R. Coombs

[jaraco]

Thank you!

---

Original comment by: Brian Neal