bug#62044: 30.0.50; ERC 5.5: Auto-reconnect is broken

[xoddf2]

J.P. writes:

> Hi xoddf2,
>
> [...] For starters, we need to find a recipe, all the way from
> emacs -Q, that triggers the unwanted behavior. That way, we can dispense
> with any possible complications arising from your init.el and any
> third-party packages [...]

After running emacs-snapshot -Q, I yanked the below Emacs Lisp code into
the *scratch* buffer, evaluated it, then ran M-x erc.  I left server and
port at default (irc.libera.chat and 6667, respectively), set nick to
aoddf2, and left the server password blank.  I then joined ##test.  I
said something in that channel from my usual client, disconnected the VM
from the network in NetworkManager Applet, and then waited a few
minutes.  I reconnected and then waited again.  ERC had still not
reconnected.

> [...]
>
> Typically, if we make it to the "Logging in as" phase, we can rule out
> TLS- and process-related issues (for now) and instead focus on logical
> connection parameters, such as the various `erc-session-foo' variables.
> If you don't mind, please do the following before connecting for the
> first time in a new -Q session:
>
>   (require 'erc)
>   (erc-toggle-debug-irc-protocol) 
>   (setq erc-server-reconnect-timeout 60)
>   (trace-function-background 'erc--register-connection)
>   (trace-function-background 'erc-auth-source-search)
>   (trace-function-background 'erc-login)
>   (trace-function-background 'erc-open)
>   (trace-function-background 'erc-open-network-stream)
>   (trace-function-background 'erc-open-tls-stream)
>   (trace-function-background 'erc-process-sentinel)
>   (trace-function-background 'erc-process-sentinel-1)
>   (trace-function-background 'erc-process-sentinel-2)
>   (trace-function-background 'erc-schedule-reconnect)
>   (trace-function-background 'erc-server-connect)
>   (trace-function-background 'erc-server-reconnect)
>
> And, after witnessing the bug, please provide the output of the
> *erc-protocol* and *trace-output* buffers (out of band, if necessary,
> though ideally with minimal redactions, aside from credentials) along
> with the -Q recipe mentioned earlier.

*erc-protocol*:

Version: 2
ERC-Version: 5.5
Emacs-Version: 30.0.50
*** This buffer displays all IRC protocol traffic exchanged with servers.
*** Kill it to disable logging.
*** Press t to toggle.*** IRC protocol logging enabled at Wed Mar  8 00:34:44 
2023

2023-03-08T00:35:02.020240-0800 irc.libera.chat:6667 >> NICK aoddf2
2023-03-08T00:35:02.020406-0800 irc.libera.chat:6667 >> USER user 0 * :unknown
2023-03-08T00:35:02.161418-0800 irc.libera.chat:6667 << :lead.libera.chat 
NOTICE * :*** Checking Ident
2023-03-08T00:35:02.469048-0800 irc.libera.chat:6667 << :lead.libera.chat 
NOTICE * :*** Looking up your hostname...
2023-03-08T00:35:03.186250-0800 irc.libera.chat:6667 << :lead.libera.chat 
NOTICE * :*** Found your hostname: [REDACTED]
2023-03-08T00:35:08.306391-0800 irc.libera.chat:6667 << :lead.libera.chat 
NOTICE * :*** No Ident response
2023-03-08T00:35:08.306787-0800 irc.libera.chat:6667 << :lead.libera.chat 001 
aoddf2 :Welcome to the Libera.Chat Internet Relay Chat Network aoddf2
2023-03-08T00:35:08.307200-0800 irc.libera.chat:6667 << :lead.libera.chat 002 
aoddf2 :Your host is lead.libera.chat[94.125.182.252/6667], running version 
solanum-1.0-dev
2023-03-08T00:35:08.307887-0800 irc.libera.chat:6667 << :lead.libera.chat 003 
aoddf2 :This server was created Thu Nov 24 2022 at 07:37:25 UTC
2023-03-08T00:35:08.308183-0800 irc.libera.chat:6667 << :lead.libera.chat 004 
aoddf2 lead.libera.chat solanum-1.0-dev DGIMQRSZaghilopsuwz 
CFILMPQRSTbcefgijklmnopqrstuvz bkloveqjfI
2023-03-08T00:35:08.308628-0800 lead.libera.chat << :lead.libera.chat 005 
aoddf2 FNC WHOX CALLERID=g ETRACE MONITOR=100 KNOCK SAFELIST ELIST=CMNTU 
CHANTYPES=# EXCEPTS INVEX CHANMODES=eIbq,k,flj,CFLMPQRSTcgimnprstuz :are 
supported by this server
2023-03-08T00:35:08.309048-0800 lead.libera.chat << :lead.libera.chat 005 
aoddf2 CHANLIMIT=#:250 PREFIX=(ov)@+ MAXLIST=bqeI:100 MODES=4 
NETWORK=Libera.Chat STATUSMSG=@+ CASEMAPPING=rfc1459 NICKLEN=16 MAXNICKLEN=16 
CHANNELLEN=50 TOPICLEN=390 DEAF=D :are supported by this server
2023-03-08T00:35:08.309509-0800 lead.libera.chat << :lead.libera.chat 005 
aoddf2 
TARGMAX=NAMES:1,LIST:1,KICK:1,WHOIS:1,PRIVMSG:4,NOTICE:4,ACCEPT:,MONITOR: 
EXTBAN=$,ajrxz :are supported by this server
2023-03-08T00:35:08.309867-0800 lead.libera.chat << :lead.libera.chat 251 
aoddf2 :There are 70 users and 50158 invisible on 28 servers
2023-03-08T00:35:08.310079-0800 lead.libera.chat << :lead.libera.chat 252 
aoddf2 37 :IRC Operators online
2023-03-08T00:35:08.310295-0800 lead.libera.chat << :lead.libera.chat 253 
aoddf2 41 :unknown connection(s)
2023-03-08T00:35:08.310504-0800 lead.libera.chat << :lead.libera.chat 254 
aoddf2 22988 :channels formed
2023-03-08T00:35:08.331744-0800 lead.libera.chat << :lead.libera.chat 255 
aoddf2 :I have 3127 clients and 1 servers
2023-03-08T00:35:08.332278-0800 lead.libera.chat << :lead.libera.chat 265 
aoddf2 3127 3449 :Current local users 3127, max 3449
2023-03-08T00:35:08.342970-0800 lead.libera.chat << :lead.libera.chat 266 
aoddf2 50228 51827 :Current global users 50228, max 51827
2023-03-08T00:35:08.343304-0800 lead.libera.chat << :lead.libera.chat 250 
aoddf2 :Highest connection count: 3450 (3449 clients) (314542 connections 
received)
2023-03-08T00:35:08.343675-0800 lead.libera.chat << :lead.libera.chat 375 
aoddf2 :- lead.libera.chat Message of the Day - 
2023-03-08T00:35:08.344067-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :- Welcome to Libera Chat, the IRC network for
2023-03-08T00:35:08.344270-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :- free & open-source software and peer directed projects.
2023-03-08T00:35:08.344460-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :-  
2023-03-08T00:35:08.344615-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :- Use of Libera Chat is governed by our network policies.
2023-03-08T00:35:08.344813-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :-  
2023-03-08T00:35:08.344974-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :- To reduce network abuses we perform open proxy checks
2023-03-08T00:35:08.345192-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :- on hosts at connection time.
2023-03-08T00:35:08.345370-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :-  
2023-03-08T00:35:08.345528-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :- Please visit us in #libera for questions and support.
2023-03-08T00:35:08.345728-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :-  
2023-03-08T00:35:08.345894-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :- Website and documentation:  https://libera.chat
2023-03-08T00:35:08.346100-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :- Webchat:                    https://web.libera.chat
2023-03-08T00:35:08.346305-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :- Network policies:           https://libera.chat/policies
2023-03-08T00:35:08.346508-0800 lead.libera.chat << :lead.libera.chat 372 
aoddf2 :- Email:                      support@libera.chat
2023-03-08T00:35:08.346694-0800 lead.libera.chat << :lead.libera.chat 376 
aoddf2 :End of /MOTD command.
2023-03-08T00:35:08.347303-0800 Libera.Chat >> MODE aoddf2 +i
2023-03-08T00:35:08.347382-0800 Libera.Chat << :aoddf2 MODE aoddf2 :+iw
2023-03-08T00:35:11.908212-0800 Libera.Chat >> JOIN ##test
2023-03-08T00:35:12.348311-0800 Libera.Chat >> PING 1678264512
2023-03-08T00:35:14.914253-0800 Libera.Chat << :aoddf2!~user@[REDACTED] JOIN 
##test
2023-03-08T00:35:14.919775-0800 Libera.Chat >> MODE ##test
2023-03-08T00:35:15.268978-0800 Libera.Chat << :lead.libera.chat 353 aoddf2 @ 
##test :aoddf2 xoddf2 lonjil2 Guest82707 jstoker
2023-03-08T00:35:15.269737-0800 Libera.Chat << :lead.libera.chat 366 aoddf2 
##test :End of /NAMES list.
2023-03-08T00:35:15.269837-0800 Libera.Chat << :lead.libera.chat PONG 
lead.libera.chat :1678264512
2023-03-08T00:35:15.678517-0800 Libera.Chat << :lead.libera.chat 324 aoddf2 
##test +Pnst
2023-03-08T00:35:15.679213-0800 Libera.Chat << :lead.libera.chat 329 aoddf2 
##test 1619537078
2023-03-08T00:35:17.932532-0800 Libera.Chat << :xoddf2!~xoddf2@user/xoddf2 
PRIVMSG ##test :...
2023-03-08T00:35:42.357025-0800 Libera.Chat >> PING 1678264542
2023-03-08T00:36:12.366140-0800 Libera.Chat >> PING 1678264572
2023-03-08T00:36:42.378078-0800 Libera.Chat >> PING 1678264602
2023-03-08T00:37:12.378084-0800 Libera.Chat >> PING 1678264632

*trace-output*:

======================================================================
1 -> (erc-open "irc.libera.chat" 6667 "aoddf2" "unknown" t nil nil nil nil nil 
"user" nil)
| 2 -> (erc-auth-source-search :user "aoddf2")
| 2 <- erc-auth-source-search: nil
| 2 -> (erc-server-connect "irc.libera.chat" 6667 #<buffer 
irc.libera.chat:6667> nil)
| | 3 -> (erc-open-network-stream "erc-irc.libera.chat-6667" nil 
"irc.libera.chat" 6667)
| | 3 <- erc-open-network-stream: #<process erc-irc.libera.chat-6667>
| 2 <- erc-server-connect: nil
1 <- erc-open: #<buffer irc.libera.chat:6667>
======================================================================
1 -> (erc-process-sentinel #<process erc-irc.libera.chat-6667> "open\n")
| 2 -> (erc--register-connection)
| | 3 -> (erc-login)
| | 3 <- erc-login: nil
| 2 <- erc--register-connection: nil
1 <- erc-process-sentinel: nil
======================================================================
1 -> (erc-auth-source-search :user "##test")
1 <- erc-auth-source-search: nil
======================================================================
1 -> (erc-open "irc.libera.chat" 6667 "aoddf2" "unknown" nil nil (#1="##test") 
#1# #<process erc-irc.libera.chat-6667> nil "user" nil)
1 <- erc-open: #<buffer ##test>
======================================================================
1 -> (erc-process-sentinel #<process erc-irc.libera.chat-6667> "deleted\n")
| 2 -> (erc-process-sentinel-1 "deleted\n" #<buffer Libera.Chat>)
| | 3 -> (erc-process-sentinel-2 "deleted\n" #<buffer Libera.Chat>)
| | | 4 -> (erc-schedule-reconnect #<buffer Libera.Chat>)
| | | 4 <- erc-schedule-reconnect: [nil 25608 18834 370932 nil 
erc-server-delayed-reconnect (#<buffer Libera.Chat>) nil 554000 nil]
| | 3 <- erc-process-sentinel-2: nil
| 2 <- erc-process-sentinel-1: nil
1 <- erc-process-sentinel: nil
======================================================================
1 -> (erc-server-reconnect)
| 2 -> (erc-open "irc.libera.chat" 6667 "aoddf2" "unknown" t nil nil nil nil 
nil "user" nil)
| | 3 -> (erc-server-connect "irc.libera.chat" 6667 #<buffer Libera.Chat> nil)
| | | 4 -> (erc-open-network-stream "erc-irc.libera.chat-6667" nil 
"irc.libera.chat" 6667)
| | | 4 <- erc-open-network-stream: #<process erc-irc.libera.chat-6667>
| | 3 <- erc-server-connect: nil
| 2 <- erc-open: #<buffer Libera.Chat>
1 <- erc-server-reconnect: nil

(Only redaction was the hostname.)

>
> Thanks again,
> J.P.


-- 
xoddf2 | https://wlair.us.to/ | PGP: 20EB90D3