From 753a39ea0a1dafff398340ddd2ed8b1360e2b08f Mon Sep 17 00:00:00 2001 From: Florian Strzelecki Date: Thu, 23 Mar 2023 23:45:26 +0100 Subject: [PATCH 1/5] irc: deprecate AbstractBot.on_error This method was used for the asynchat backend implementation. It is now deprecated and must not be used. Co-authored-by: dgw --- sopel/irc/__init__.py | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/sopel/irc/__init__.py b/sopel/irc/__init__.py index 4d9a6b453..069a1fde1 100644 --- a/sopel/irc/__init__.py +++ b/sopel/irc/__init__.py @@ -448,13 +448,19 @@ def on_message_sent(self, raw: str) -> None: ) self.dispatch(pretrigger) + @deprecated( + 'This method was used to log errors with asynchat; ' + 'use logging.getLogger("sopel.exception") instead.', + version='8.0', + removed_in='9.0', + ) def on_error(self) -> None: """Handle any uncaptured error in the bot itself.""" LOGGER.error('Fatal error in core, please review exceptions log.') err_log = logging.getLogger('sopel.exceptions') err_log.error( - 'Fatal error in core, handle_error() was called.\n' + 'Fatal error in core, bot.on_error() was called.\n' 'Last Line:\n%s', self.last_raw_line, ) From b6c5e864ce4025cffaa9a292884917f6a4dcc778 Mon Sep 17 00:00:00 2001 From: Florian Strzelecki Date: Fri, 24 Mar 2023 00:42:12 +0100 Subject: [PATCH 2/5] irc: user-friendly messages on connection error These error are now managed with a more user-friendly message, and the exception is sent to the exception log file: * SSL certificate validation error * SSL generic error * Connection timeout (socket timeout, not IRC timeout) * Invalid hostname * Unable to connect (temporary disconnected, host unreachable, etc.) If we inspect the OSError's errno we could provide a more fine-grained error handling. We could, also, improve the connection retry for certain errors. --- sopel/irc/abstract_backends.py | 12 ++++++ sopel/irc/backends.py | 74 +++++++++++++++++++++++++++++++--- 2 files changed, 81 insertions(+), 5 deletions(-) diff --git a/sopel/irc/abstract_backends.py b/sopel/irc/abstract_backends.py index e8b8ba914..080e9325d 100644 --- a/sopel/irc/abstract_backends.py +++ b/sopel/irc/abstract_backends.py @@ -15,6 +15,7 @@ from __future__ import annotations import abc +import logging from typing import Optional, TYPE_CHECKING from .utils import safe @@ -41,6 +42,17 @@ def __init__(self, bot: AbstractBot): def is_connected(self) -> bool: """Tell if the backend is connected or not.""" + def log_exception(self) -> None: + """Log an exception to ``sopel.exceptions``. + + The IRC backend must use this method to log any exception that isn't + caught by the bot itself (i.e. while handling messages), such as + connection errors, SSL errors, etc. + """ + err_log = logging.getLogger('sopel.exceptions') + err_log.exception('Exception in core') + err_log.error('----------------------------------------') + @abc.abstractmethod def on_irc_error(self, pretrigger: PreTrigger) -> None: """Action to perform when the server sends an error event. diff --git a/sopel/irc/backends.py b/sopel/irc/backends.py index 0ccf5f286..b276ca534 100644 --- a/sopel/irc/backends.py +++ b/sopel/irc/backends.py @@ -17,6 +17,7 @@ import asyncio import logging import signal +import socket import ssl import threading from typing import Dict, List, Optional, Tuple, TYPE_CHECKING @@ -379,6 +380,7 @@ def get_connection_kwargs(self) -> Dict: async def _run_forever(self) -> None: self._loop = asyncio.get_running_loop() + connection_kwargs = self.get_connection_kwargs() # register signal handlers for quit_signal in QUIT_SIGNALS: @@ -389,16 +391,78 @@ async def _run_forever(self) -> None: # open connection try: self._reader, self._writer = await asyncio.open_connection( - **self.get_connection_kwargs(), + **connection_kwargs, ) - except ssl.SSLError: - LOGGER.exception('Unable to connect due to SSL error.') + + # SSL Error + except ssl.SSLCertVerificationError as err: + LOGGER.error( + 'Unable to connect due to an SSL validation error: %s', + err, + ) + self.log_exception() + # tell the bot to quit without restart + self.bot.hasquit = True + self.bot.wantsrestart = False + return + except ssl.SSLError as err: + LOGGER.error('Unable to connect due to an SSL error: %s', err) + self.log_exception() + # tell the bot to quit without restart + self.bot.hasquit = True + self.bot.wantsrestart = False + return + + # Specific connection error + except socket.gaierror as err: + LOGGER.error( + 'Unable to connect due to invalid IRC server address: %s', + err, + ) + LOGGER.error( + 'You should verify that "%s:%s" is the correct address ' + 'to connect to the IRC server.', + connection_kwargs.get('host'), + connection_kwargs.get('port'), + ) + self.log_exception() # tell the bot to quit without restart self.bot.hasquit = True self.bot.wantsrestart = False return - except Exception: - LOGGER.exception('Unable to connect.') + except TimeoutError as err: + LOGGER.error('Unable to connect due to a timeout: %s', err) + self.log_exception() + # tell the bot to quit without restart + self.bot.hasquit = True + self.bot.wantsrestart = False + return + + # Generic connection error (OSError is used for any connection error) + except OSError as err: + LOGGER.error( + 'Unable to connect: %s', + err, + ) + LOGGER.error( + 'You should verify that "%s:%s" is the correct address ' + 'to connect to the IRC server.', + connection_kwargs.get('host'), + connection_kwargs.get('port'), + ) + self.log_exception() + # tell the bot to quit without restart + self.bot.hasquit = True + self.bot.wantsrestart = False + return + + # Unexpected error + except Exception as err: + LOGGER.error( + 'Unable to connect due to an unexpected error: %s', + err, + ) + self.log_exception() # until there is a way to prevent an infinite loop of connection # error and reconnect, we have to tell the bot to quit here # TODO: prevent infinite connection failure loop From 3a81afa66342eb6db6b49aff3ddfce89ba64da84 Mon Sep 17 00:00:00 2001 From: Florian Strzelecki Date: Fri, 24 Mar 2023 23:48:51 +0100 Subject: [PATCH 3/5] irc: friendler message on certificate verification failure Co-authored-by: James Gerity --- sopel/irc/backends.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sopel/irc/backends.py b/sopel/irc/backends.py index b276ca534..9db5061fe 100644 --- a/sopel/irc/backends.py +++ b/sopel/irc/backends.py @@ -397,7 +397,7 @@ async def _run_forever(self) -> None: # SSL Error except ssl.SSLCertVerificationError as err: LOGGER.error( - 'Unable to connect due to an SSL validation error: %s', + 'Unable to connect due to SSL certificate verification failure: %s', err, ) self.log_exception() From 96a52ac5d00738f93bfc0c59946360aa83c4896a Mon Sep 17 00:00:00 2001 From: Florian Strzelecki Date: Sat, 8 Apr 2023 22:16:30 +0200 Subject: [PATCH 4/5] irc: separate ConnectionError from OSError Co-authored-by: dgw --- sopel/irc/backends.py | 23 +++++++++++++++-------- 1 file changed, 15 insertions(+), 8 deletions(-) diff --git a/sopel/irc/backends.py b/sopel/irc/backends.py index 9db5061fe..f066bfb69 100644 --- a/sopel/irc/backends.py +++ b/sopel/irc/backends.py @@ -394,10 +394,11 @@ async def _run_forever(self) -> None: **connection_kwargs, ) - # SSL Error + # SSL Errors (certificate verification and generic SSL errors) except ssl.SSLCertVerificationError as err: LOGGER.error( - 'Unable to connect due to SSL certificate verification failure: %s', + 'Unable to connect due to ' + 'SSL certificate verification failure: %s', err, ) self.log_exception() @@ -413,7 +414,7 @@ async def _run_forever(self) -> None: self.bot.wantsrestart = False return - # Specific connection error + # Specific connection error (invalid address and timeout) except socket.gaierror as err: LOGGER.error( 'Unable to connect due to invalid IRC server address: %s', @@ -438,12 +439,18 @@ async def _run_forever(self) -> None: self.bot.wantsrestart = False return - # Generic connection error (OSError is used for any connection error) + # Generic connection error + except ConnectionError as err: + LOGGER.error('Unable to connect: %s', err) + self.log_exception() + # tell the bot to quit without restart + self.bot.hasquit = True + self.bot.wantsrestart = False + return + + # Generic OSError (used for any unspecific connection error) except OSError as err: - LOGGER.error( - 'Unable to connect: %s', - err, - ) + LOGGER.error('Unable to connect: %s', err) LOGGER.error( 'You should verify that "%s:%s" is the correct address ' 'to connect to the IRC server.', From c4a34f70b38fb4444f7eb86a380f6e3ddd809a4d Mon Sep 17 00:00:00 2001 From: Florian Strzelecki Date: Sat, 8 Apr 2023 22:43:33 +0200 Subject: [PATCH 5/5] irc: isolate the socket connection attempt Co-authored-by: dgw --- sopel/irc/backends.py | 53 +++++++++++++++++++++++++++---------------- 1 file changed, 34 insertions(+), 19 deletions(-) diff --git a/sopel/irc/backends.py b/sopel/irc/backends.py index f066bfb69..cdfd6bb42 100644 --- a/sopel/irc/backends.py +++ b/sopel/irc/backends.py @@ -57,7 +57,7 @@ def __init__( ): super().__init__(bot) - def is_connected(self) -> False: + def is_connected(self) -> bool: """Check if the backend is connected to an IRC server. **Always returns False:** This backend type is never connected. @@ -378,19 +378,18 @@ def get_connection_kwargs(self) -> Dict: 'local_addr': self._source_address, } - async def _run_forever(self) -> None: - self._loop = asyncio.get_running_loop() - connection_kwargs = self.get_connection_kwargs() - - # register signal handlers - for quit_signal in QUIT_SIGNALS: - self._loop.add_signal_handler(quit_signal, self._signal_quit) - for restart_signal in RESTART_SIGNALS: - self._loop.add_signal_handler(restart_signal, self._signal_restart) + async def _connect_to_server( + self, **connection_kwargs + ) -> Tuple[ + Optional[asyncio.StreamReader], + Optional[asyncio.StreamWriter], + ]: + reader: Optional[asyncio.StreamReader] = None + writer: Optional[asyncio.StreamWriter] = None # open connection try: - self._reader, self._writer = await asyncio.open_connection( + reader, writer = await asyncio.open_connection( **connection_kwargs, ) @@ -405,14 +404,12 @@ async def _run_forever(self) -> None: # tell the bot to quit without restart self.bot.hasquit = True self.bot.wantsrestart = False - return except ssl.SSLError as err: LOGGER.error('Unable to connect due to an SSL error: %s', err) self.log_exception() # tell the bot to quit without restart self.bot.hasquit = True self.bot.wantsrestart = False - return # Specific connection error (invalid address and timeout) except socket.gaierror as err: @@ -430,14 +427,12 @@ async def _run_forever(self) -> None: # tell the bot to quit without restart self.bot.hasquit = True self.bot.wantsrestart = False - return except TimeoutError as err: LOGGER.error('Unable to connect due to a timeout: %s', err) self.log_exception() # tell the bot to quit without restart self.bot.hasquit = True self.bot.wantsrestart = False - return # Generic connection error except ConnectionError as err: @@ -446,7 +441,6 @@ async def _run_forever(self) -> None: # tell the bot to quit without restart self.bot.hasquit = True self.bot.wantsrestart = False - return # Generic OSError (used for any unspecific connection error) except OSError as err: @@ -461,7 +455,6 @@ async def _run_forever(self) -> None: # tell the bot to quit without restart self.bot.hasquit = True self.bot.wantsrestart = False - return # Unexpected error except Exception as err: @@ -475,13 +468,34 @@ async def _run_forever(self) -> None: # TODO: prevent infinite connection failure loop self.bot.hasquit = True self.bot.wantsrestart = False - return - self._connected = True + return reader, writer + + async def _run_forever(self) -> None: + self._loop = asyncio.get_running_loop() + connection_kwargs = self.get_connection_kwargs() + + # register signal handlers + for quit_signal in QUIT_SIGNALS: + self._loop.add_signal_handler(quit_signal, self._signal_quit) + for restart_signal in RESTART_SIGNALS: + self._loop.add_signal_handler(restart_signal, self._signal_restart) + # connect to socket + LOGGER.debug('Attempt connection.') + self._reader, self._writer = await self._connect_to_server( + **connection_kwargs + ) + if not self._reader or not self._writer: + LOGGER.debug('Connection attempt failed.') + return + + # on socket connection LOGGER.debug('Connection registered.') + self._connected = True self.bot.on_connect() + # read forever LOGGER.debug('Waiting for messages...') self._read_task = asyncio.create_task(self.read_forever()) try: @@ -491,6 +505,7 @@ async def _run_forever(self) -> None: else: LOGGER.debug('Reader received EOF.') + # on socket disconnection self._connected = False # cancel timeout tasks