sopel-irc / sopel

:robot::speech_balloon: An easy-to-use and highly extensible IRC Bot framework. Formerly Willie.
https://sopel.chat
Other
950 stars 405 forks source link

Ctrl-C doesn't work during connection phase #2408

Open dgw opened 1 year ago

dgw commented 1 year ago

Description

In between loading plugins and when the IRC connection finishes registering, it seems impossible to quit Sopel in the normal way using Ctrl-C.

Somewhat similar to #1705, but a different phase of startup.

Reproduction steps

  1. Find or simulate a poor quality network: low-ish speed, high latency\ Speedtest says I have 33/9 Mbps & 80ms ping, but throughput to my test IRC net is probably worse
  2. Run sopel
  3. Wait for plugins to finish loading (INFO log line)\ If DEBUG logs are turned on, the line to look for is "Using selector: EpollSelector" from asyncio
  4. Press Ctrl-C
  5. Sopel reports "Receiving QUIT signal." but does not exit

Expected behavior

Sopel should exit after it receives and acknowledges the QUIT signal.

Relevant logs

[2023-02-03 06:21:47,785] sopel.bot            INFO     - Registered 25 plugins, 1 failed, 32 disabled
[2023-02-03 06:21:47,787] sopel.irc.backends   DEBUG    - Running forever.
[2023-02-03 06:21:47,787] asyncio              DEBUG    - Using selector: EpollSelector
^C[2023-02-03 06:21:57,195] sopel.irc.backends   INFO     - Receiving QUIT signal.
^C[2023-02-03 06:22:05,328] sopel.irc.backends   INFO     - Receiving QUIT signal.
[2023-02-03 06:22:09,458] sopel.irc.backends   DEBUG    - Connection registered.
[2023-02-03 06:22:09,458] sopel.irc            INFO     - Connected, initiating setup sequence

<...>

[2023-02-03 06:22:12,022] sopel.coretasks      INFO     - Joining 1 channels (with JOIN throttle OFF); this may take a moment.
[2023-02-03 06:22:12,024] sopel.coretasks      DEBUG    - Ignoring user modes: ['SopelTest', '+Six']
^C[2023-02-03 06:22:22,403] sopel.irc.backends   INFO     - Receiving QUIT signal.
[2023-02-03 06:22:22,601] sopel.irc            ERROR    - ERROR received from server: Closing Link: 2605:59c8:51d8:4710:20a8:311b:xxxx:xxxx ()
[2023-02-03 06:22:22,602] sopel.irc.backends   WARNING  - Error received from server: Closing Link: 2605:59c8:51d8:4710:20a8:311b:xxxx:xxxx ()
[2023-02-03 06:22:22,603] sopel.irc.backends   WARNING  - Receiving partial message from IRC.
[2023-02-03 06:22:22,603] sopel.irc.backends   DEBUG    - No data received.
[2023-02-03 06:22:22,604] sopel.irc.backends   DEBUG    - Reader received EOF.
[2023-02-03 06:22:22,604] sopel.irc.backends   DEBUG    - Shutting down writer.
[2023-02-03 06:22:22,605] sopel.irc.backends   DEBUG    - All clear, exiting now.
[2023-02-03 06:22:22,606] sopel.irc.backends   INFO     - Connection backend stopped.
[2023-02-03 06:22:22,607] sopel.bot            INFO     - Shutting down

<rest of shutdown sequence is nominal/irrelevant>

Notes

This issue is most noticeable on a network connection with high latency. I can reproduce it naturally this week because I'm on vacation and the only Internet access available is through Starlink, but there are certainly Linux utilities to simulate similar conditions without having to travel 2000 miles like I did. 😉

No need to block 8.0 for this; edge cases in signal handling have existed for a long time, back through 7.x and earlier. I just wanted to document that this particular case exists so we can work on it for 8.1.

Sopel version

f527b13d3e508d7147b99f357a93593af2542d8f

Installation method

pip install

Python version

3.9.5

Operating system

Ubuntu 20.04 (WSL 1)

IRCd

No response

Relevant plugins

No response

dgw commented 12 months ago

Quick note: Reconfirmed with commit 6af4f23d2ea011aa1e5fc9ce5449b2f2bce1bd1c under Python 3.10 on Termux.