Logging to IRC creates errors after QUIT

[dgw]

Description

The IrcLoggingHandler trips its handleError() method with log output immediately after sending a QUIT to the server.

Reproduction steps

1. Enable outputting logs to an IRC channel with logging_channel = #somechannel
2. Set Sopel to flood its IRC logging handler with logging_channel_level = DEBUG
3. Start the bot
4. Quit the bot with e.g. Ctrl+C

The WARNING ("sending QUIT to server") and replying ERROR ("ERROR received from server: Closing Link") never make it to the IRC channel. The subsequent INFO ("Closing connection") generates an exception in the logger itself (BrokenPipeError: [Errno32] Broken pipe). Full logs below.

Expected behavior

Ideally the WARNING about sending a QUIT command should appear on IRC before the actual QUIT is sent/processed, but that's not the deal-breaker here. Neither is the ERROR not making it there; obviously, the bot has already quit (the server is acknowledging it), so the logger can't send anything more to IRC.

What bugs me is the BrokenPipeError. I expect the IrcLoggingHandler to check and realize that it doesn't have a connection, and then not even try to send anything to IRC after the QUIT is processed.

Logs

Long traceback

^C[2022-02-12 17:30:13,217] sopel.bot            WARNING  - Got quit signal, sending QUIT to server.
[2022-02-12 17:30:13,248] sopel.irc            ERROR    - ERROR received from server: Closing Link: 68-nn-nn-nn.fttp.usinternet.com ()
[2022-02-12 17:30:13,249] sopel.irc.backends   INFO     - Closing connection
--- Logging error ---
Traceback (most recent call last):
  File "/mnt/c/Users/dgw/github/sopel/sopel/logger.py", line 37, in emit
    self._bot.say(msg, self._channel)
  File "/mnt/c/Users/dgw/github/sopel/sopel/irc/__init__.py", line 760, in say
    self.backend.send_privmsg(recipient, text)
  File "/mnt/c/Users/dgw/github/sopel/sopel/irc/abstract_backends.py", line 201, in send_privmsg
    self.send_command('PRIVMSG', safe(dest), text=text)
  File "/mnt/c/Users/dgw/github/sopel/sopel/irc/abstract_backends.py", line 69, in send_command
    self.irc_send(raw_command.encode('utf-8'))
  File "/mnt/c/Users/dgw/github/sopel/sopel/irc/backends.py", line 125, in irc_send
    self.send(data)
  File "/mnt/c/Users/dgw/github/sopel/sopel/irc/backends.py", line 322, in send
    result = self.socket.send(data)
  File "/usr/lib/python3.9/ssl.py", line 1173, in send
    return self._sslobj.write(data)
BrokenPipeError: [Errno 32] Broken pipe
Call stack:
  File "/home/dgw/.local/bin/sopel", line 11, in <module>
    load_entry_point('sopel', 'console_scripts', 'sopel')()
  File "/mnt/c/Users/dgw/github/sopel/sopel/cli/run.py", line 509, in main
    return command(opts)
  File "/mnt/c/Users/dgw/github/sopel/sopel/cli/run.py", line 363, in command_start
    ret = run(settings, pid_file_path)
  File "/mnt/c/Users/dgw/github/sopel/sopel/cli/run.py", line 93, in run
    p.run(settings.core.host, int(settings.core.port))
  File "/mnt/c/Users/dgw/github/sopel/sopel/irc/__init__.py", line 234, in run
    self.backend.run_forever()
  File "/mnt/c/Users/dgw/github/sopel/sopel/irc/backends.py", line 130, in run_forever
    asyncore.loop()
  File "/usr/lib/python3.9/asyncore.py", line 203, in loop
    poll_fun(timeout, map)
  File "/usr/lib/python3.9/asyncore.py", line 150, in poll
    read(obj)
  File "/usr/lib/python3.9/asyncore.py", line 83, in read
    obj.handle_read_event()
  File "/usr/lib/python3.9/asyncore.py", line 420, in handle_read_event
    self.handle_read()
  File "/usr/lib/python3.9/asynchat.py", line 171, in handle_read
    self.found_terminator()
  File "/mnt/c/Users/dgw/github/sopel/sopel/irc/backends.py", line 229, in found_terminator
    self.bot.on_message(line)
  File "/mnt/c/Users/dgw/github/sopel/sopel/irc/__init__.py", line 283, in on_message
    self.backend.on_irc_error(pretrigger)
  File "/mnt/c/Users/dgw/github/sopel/sopel/irc/backends.py", line 114, in on_irc_error
    self.handle_close()
  File "/mnt/c/Users/dgw/github/sopel/sopel/irc/backends.py", line 177, in handle_close
    LOGGER.info('Closing connection')
  File "/usr/lib/python3.9/logging/__init__.py", line 1446, in info
    self._log(INFO, msg, args, **kwargs)
  File "/usr/lib/python3.9/logging/__init__.py", line 1589, in _log
    self.handle(record)
  File "/usr/lib/python3.9/logging/__init__.py", line 1599, in handle
    self.callHandlers(record)
  File "/usr/lib/python3.9/logging/__init__.py", line 1661, in callHandlers
    hdlr.handle(record)
  File "/usr/lib/python3.9/logging/__init__.py", line 952, in handle
    self.emit(record)
  File "/mnt/c/Users/dgw/github/sopel/sopel/logger.py", line 41, in emit
    self.handleError(record)
Message: 'Closing connection'
Arguments: ()
[2022-02-12 17:30:14,354] sopel.bot            INFO     - Shutting down
[2022-02-12 17:30:14,354] sopel.bot            INFO     - Stopping the Job Scheduler.
[2022-02-12 17:30:14,628] sopel.bot            INFO     - Job Scheduler stopped.
[2022-02-12 17:30:14,629] sopel.bot            INFO     - Calling shutdown for 2 plugins.

Environment

• Sopel .version: 365cad7
• Sopel installed via: source
• Python version: 3.9.5
• Operating system: Ubuntu 18.04 (in WSL2)
• IRCd /version: plexus-4(hybrid-8.1.20)
• Relevant plugins: n/a

Notes

In fact, the IrcLoggingHandler does check that the connection is open first:

sopel/sopel/logger.py

Lines 31 to 33 in b58b5c3

	if self._bot.backend is None or not self._bot.backend.is_connected():
	# Don't emit logs when the bot is not connected.
	return

But for whatever reason (race condition?), the check doesn't go as expected and emit() tries to write to the socket after it's closed.

Tangentially, nowhere in the method chain from bot.Sopel.say() all the way through irc.AbstractBot.say() and the concrete implementations of the underlying backend send_privmsg(), send_command(), irc_send(), etc. methods—nothing actually checks to make sure the command isn't being sent to a connection that isn't open, and there's obviously no error handling for such a case.

Fun stuff

My original motivation for testing this was actually a problem with logging_channel = #somechan + logging_channel_level = DEBUG. That combination (on another system, under Python 3.8 / Ubuntu 20.04 / WSL1) generated repeated errors about flooding, and I was trying to pin down the reproduction for a "real report" I hinted at in #2250. I wasn't able to reproduce the bug I was looking for (yet?), but it's still worth tracking the one I did find.

[dgw]

Testing #2419 convinced me that this is mitigated with the changes to connection tests.