bug#54087: 28.0.91; rcirc: irc.gnome reg timeout; reconnects after /quit

bug#54087: 28.0.91; rcirc: irc.gnome reg timeout; reconnects after /quit

[Ken Raeburn]

I'm running emacs 28.0.91 as packaged for Fedora 34 by bhavin192, in a
recently created F34 virtual machine, so a fairly fresh environment. The
.emacs file settings are slightly customized:

 '(rcirc-reconnect-delay 10)
 '(rcirc-server-alist
   '(("irc.libera.chat" :nick "raeburn" :port 6697 :password <ELIDED> :channels
      ("#emacs" "#rcirc")
      :encryption tls)
     ("irc.gnome.org" :nick "raeburn" :channels
      ("#gnucash"))))
 '(rcirc-time-format "%FT%T ")

1) Since I was already signed onto irc.gnome.org from elsewhere, my
login as "raeburn" was rejected, and it always timed out trying to
register as "raeburn`":

    09:52 -irc2.acc.umu.se- *** Looking up your hostname...
    09:52 -irc2.acc.umu.se- *** Found your hostname (cached)
    09:52 *** irc2.acc.umu.se 433 raeburn Nickname is already in use.
    09:52 !!! Closing Link: raeburn`[24.60.138.149] (Registration
              Timeout)

(This was before I changed the time format.) This happened over and over
(not stopping at 3 tries, which is the value of
rcirc-reconnect-attempts), with multiple server hosts. Typing "/quit" in
the server buffer does get it to stop, *if* done after "Nickname is
already in use".

It's unclear to me from reading wiki.gnome.org whether irc.gnome.org
requires or merely recommends pre-registering IRC nicknames; I see
people on with "1" or "_" or "_afk" suffixes on their names so I suspect
it's not required. So I don't know what would be leading to the timeout.

The debug log recorded this:

    [2022-02-21T10:53:10 irc.gnome.org] SENTINEL: #<process irc.gnome.org> "open
    "
    [2022-02-21T10:53:10 irc.gnome.org] CAP REQ :message-tags
    [2022-02-21T10:53:10 irc.gnome.org] CAP REQ :server-time
    [2022-02-21T10:53:10 irc.gnome.org] CAP REQ :batch
    [2022-02-21T10:53:10 irc.gnome.org] CAP REQ :message-ids
    [2022-02-21T10:53:10 irc.gnome.org] CAP REQ :invite-notify
    [2022-02-21T10:53:10 irc.gnome.org] CAP REQ :sasl
    [2022-02-21T10:53:10 irc.gnome.org] CAP REQ :multi-prefix
    [2022-02-21T10:53:10 irc.gnome.org] CAP REQ :standard-replies
    [2022-02-21T10:53:10 irc.gnome.org] NICK raeburn
    [2022-02-21T10:53:10 irc.gnome.org] USER user 0 * :unknown
    [2022-02-21T10:53:10 irc.gnome.org] :irc4.acc.umu.se NOTICE * :*** Looking up your hostname...
    [2022-02-21T10:53:10 irc.gnome.org] :irc4.acc.umu.se NOTICE * :*** Found your hostname
    [2022-02-21T10:53:12 irc.gnome.org] :irc4.acc.umu.se CAP * ACK :message-tags 
    :irc4.acc.umu.se CAP * ACK :server-time 
    :irc4.acc.umu.se CAP * ACK :batch 
    :irc4.acc.umu.se CAP * NAK :message-ids
    :irc4.acc.umu.se CAP * NAK :invite-notify
    :irc4.acc.umu.se CAP * ACK :sasl 
    :irc4.acc.umu.se CAP * ACK :multi-prefix 
    :irc4.acc.umu.se CAP * NAK :standard-replies
    :irc4.acc.umu.se 433 * raeburn :Nickname is already in use.
    [2022-02-21T10:53:12 irc.gnome.org] NICK raeburn`
    [2022-02-21T10:53:12 irc.gnome.org] PING :93915F19
    [2022-02-21T10:53:12 irc.gnome.org] PONG :93915F19
    [2022-02-21T10:53:41 irc.gnome.org] ERROR :Closing Link: raeburn`[<<IP>>] (Registration Timeout)
    [2022-02-21T10:53:41 irc.gnome.org] SENTINEL: #<process irc.gnome.org> "connection broken by remote peer
    "
    [2022-02-21T10:53:42 irc.gnome.org] SENTINEL: #<process irc.gnome.org> "open
    "


2) I got signed into irc.libera.chat as "raeburn`", but if I type
"/quit" in the #emacs buffer, it disconnects me ... and then reconnects
me. Same with typing "/quit" in *irc.libera.chat*. Reconnecting
automatically when disconnected on a network error is great, but being
unable to disconnect and stay that way when I want to is taking it a
little far, I think. :-)

    2022-02-21T09:57:19 /quit
    2022-02-21T09:57:20 *** raeburn` QUIT Client Quit
    2022-02-21T09:57:20 !!! Closing Link: c-24-60-138-149.hsd1.ma.comcast.net
                            (Client Quit)
    2022-02-21T09:57:31 *** zinc.libera.chat 433 raeburn Nickname is already in use.
    2022-02-21T09:57:34 *** zinc.libera.chat 001 Welcome to the Libera.Chat Internet Relay Chat
                                                 Network raeburn`





In GNU Emacs 28.0.91 (build 1, x86_64-redhat-linux-gnu, GTK+ Version 3.24.30, cairo version 1.17.4)
 of 2022-01-11 built on c817772a5dc24b448259fd330c6e2d67
Windowing system distributor 'The X.Org Foundation', version 11.0.12101003
System Description: Fedora 34 (Cloud Edition)

Configured using:
 'configure --build=x86_64-redhat-linux-gnu
 --host=x86_64-redhat-linux-gnu --program-prefix=
 --disable-dependency-tracking --prefix=/usr --exec-prefix=/usr
 --bindir=/usr/bin --sbindir=/usr/sbin --sysconfdir=/etc
 --datadir=/usr/share --includedir=/usr/include --libdir=/usr/lib64
 --libexecdir=/usr/libexec --localstatedir=/var
 --sharedstatedir=/var/lib --mandir=/usr/share/man
 --infodir=/usr/share/info --with-dbus --with-gif --with-jpeg --with-png
 --with-rsvg --with-tiff --with-xft --with-xpm --with-x-toolkit=gtk3
 --with-gpm=no --with-xwidgets --with-modules --with-harfbuzz
 --with-cairo --with-json --with-native-compilation
 build_alias=x86_64-redhat-linux-gnu host_alias=x86_64-redhat-linux-gnu
 CC=gcc 'CFLAGS=-DMAIL_USE_LOCKF -O2 -flto=auto -ffat-lto-objects
 -fexceptions -g -grecord-gcc-switches -pipe -Wall
 -Werror=format-security -Wp,-D_FORTIFY_SOURCE=2
 -Wp,-D_GLIBCXX_ASSERTIONS
 -specs=/usr/lib/rpm/redhat/redhat-hardened-cc1 -fstack-protector-strong
 -specs=/usr/lib/rpm/redhat/redhat-annobin-cc1 -m64 -mtune=generic
 -fasynchronous-unwind-tables -fstack-clash-protection -fcf-protection'
 LDFLAGS=-Wl,-z,relro
 PKG_CONFIG_PATH=:/usr/lib64/pkgconfig:/usr/share/pkgconfig'

Configured features:
ACL CAIRO DBUS FREETYPE GIF GLIB GMP GNUTLS GSETTINGS HARFBUZZ JPEG JSON
LIBOTF LIBSELINUX LIBSYSTEMD LIBXML2 M17N_FLT MODULES NATIVE_COMP NOTIFY
INOTIFY PDUMPER PNG RSVG SECCOMP SOUND THREADS TIFF TOOLKIT_SCROLL_BARS
X11 XDBE XIM XPM XWIDGETS GTK3 ZLIB

Important settings:
  value of $LANG: en_US.UTF-8
  value of $XMODIFIERS: @im=ibus
  locale-coding-system: utf-8-unix

Major mode: rcirc

Minor modes in effect:
  tooltip-mode: t
  global-eldoc-mode: t
  show-paren-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  tool-bar-mode: t
  use-hard-newlines: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  blink-cursor-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  line-number-mode: t
  indent-tabs-mode: t
  transient-mark-mode: t

Load-path shadows:
None found.

Features:
(shadow sort mail-extr emacsbug message dired dired-loaddefs rfc822 mml
mml-sec epa derived epg rfc6068 epg-config gnus-util rmail
rmail-loaddefs text-property-search mm-decode mm-bodies mm-encode
mail-parse rfc2231 mailabbrev gmm-utils mailheader sendmail rfc2047
rfc2045 ietf-drums mm-util mail-prsvr mail-utils thread backtrace novice
apropos mule-util cl-extra help-mode disp-table gnutls network-stream
puny nsm rmc misearch multi-isearch cus-edit pp cus-start cus-load
wid-edit rcirc parse-time iso8601 auth-source cl-seq eieio eieio-core
cl-macs eieio-loaddefs password-cache json map seq byte-opt gv bytecomp
byte-compile cconv time-date subr-x ring thingatpt cl-loaddefs cl-lib
find-func iso-transl tooltip eldoc paren electric uniquify ediff-hook
vc-hooks lisp-float-type elisp-mode mwheel term/x-win x-win
term/common-win x-dnd tool-bar dnd fontset image regexp-opt fringe
tabulated-list replace newcomment text-mode lisp-mode prog-mode register
page tab-bar menu-bar rfn-eshadow isearch easymenu timer select
scroll-bar mouse jit-lock font-lock syntax font-core term/tty-colors
frame minibuffer cl-generic cham georgian utf-8-lang misc-lang
vietnamese tibetan thai tai-viet lao korean japanese eucjp-ms cp51932
hebrew greek romanian slovak czech european ethiopic indian cyrillic
chinese composite emoji-zwj charscript charprop case-table epa-hook
jka-cmpr-hook help simple abbrev obarray cl-preloaded nadvice button
loaddefs faces cus-face macroexp files window text-properties overlay
sha1 md5 base64 format env code-pages mule custom widget
hashtable-print-readable backquote threads xwidget-internal dbusbind
inotify dynamic-setting system-font-setting font-render-setting cairo
move-toolbar gtk x-toolkit x multi-tty make-network-process
native-compile emacs)

Memory information:
((conses 16 166417 5901)
 (symbols 48 9322 0)
 (strings 32 28619 1978)
 (string-bytes 1 926876)
 (vectors 16 19201)
 (vector-slots 8 375586 10944)
 (floats 8 42 110)
 (intervals 56 5139 338)
 (buffers 992 23))

bug#54087: 28.0.91; rcirc: irc.gnome reg timeout; reconnects after quit

[Ken Raeburn]

Turns out the timeout from irc.gnome.org had nothing to do with 
switching to the alternate name "raeburn`" ... I tried emacs-28.0.91 on 
my main work laptop without any other IRC sessions going, and it still 
got timeouts from irc.gnome.org, just without the nickname-in-use error 
first this time.

Also, this time I tried connecting to an internal company IRC server, 
and hit two problems:

1) First, I forgot to bring up my VPN, so internal DNS was unavailable 
and the server name couldn't be resolved. All that was reported in the 
IRC server buffer was that the connection failed, no reason given.

2) After I got the VPN up, it could connect, but the server kept closing 
the connection. Running it with the debug flag set:

[2022-02-22T01:36:25 $irchost] SENTINEL: #<process $irchost> "open
"
[2022-02-22T01:36:25 $irchost] CAP REQ :message-tags
[2022-02-22T01:36:25 $irchost] CAP REQ :server-time
[2022-02-22T01:36:25 $irchost] CAP REQ :batch
[2022-02-22T01:36:25 $irchost] CAP REQ :message-ids
[2022-02-22T01:36:25 $irchost] CAP REQ :invite-notify
[2022-02-22T01:36:25 $irchost] CAP REQ :sasl
[2022-02-22T01:36:25 $irchost] CAP REQ :multi-prefix
[2022-02-22T01:36:25 $irchost] CAP REQ :standard-replies
[2022-02-22T01:36:25 $irchost] NICK raeburn
[2022-02-22T01:36:25 $irchost] USER user 0 * :unknown
[2022-02-22T01:36:25 $irchost] NOTICE AUTH :*** Processing connection to 
$irchost
[2022-02-22T01:36:25 $irchost] NOTICE AUTH :*** Looking up your hostname...
NOTICE AUTH :*** Checking Ident
NOTICE AUTH :*** Couldn't look up your hostname
[2022-02-22T01:37:02 $irchost] SENTINEL: #<process $irchost> "connection 
broken by remote peer
"
[2022-02-22T01:37:02 $irchost] SENTINEL: #<process $irchost> "open
"
[2022-02-22T01:37:02 $irchost] CAP REQ :message-tags
[2022-02-22T01:37:02 $irchost] CAP REQ :server-time
[2022-02-22T01:37:02 $irchost] CAP REQ :batch
[2022-02-22T01:37:02 $irchost] CAP REQ :message-ids
[2022-02-22T01:37:02 $irchost] CAP REQ :invite-notify
[2022-02-22T01:37:02 $irchost] CAP REQ :sasl
[2022-02-22T01:37:02 $irchost] CAP REQ :multi-prefix
[2022-02-22T01:37:02 $irchost] CAP REQ :standard-replies
[2022-02-22T01:37:02 $irchost] NICK raeburn
[2022-02-22T01:37:02 $irchost] USER user 0 * :unknown
[2022-02-22T01:37:09 $irchost] SENTINEL: #<process $irchost> "connection 
broken by remote peer
"

[2022-02-22T01:37:57 $irchost] SENTINEL: #<process $irchost> "open
"
[2022-02-22T01:37:57 $irchost] CAP REQ :message-tags
[2022-02-22T01:37:57 $irchost] CAP REQ :server-time
[2022-02-22T01:37:57 $irchost] CAP REQ :batch
[2022-02-22T01:37:57 $irchost] CAP REQ :message-ids
[2022-02-22T01:37:57 $irchost] CAP REQ :invite-notify
[2022-02-22T01:37:57 $irchost] CAP REQ :sasl
[2022-02-22T01:37:57 $irchost] CAP REQ :multi-prefix
[2022-02-22T01:37:57 $irchost] CAP REQ :standard-replies
[2022-02-22T01:37:57 $irchost] NICK raeburn
[2022-02-22T01:37:57 $irchost] USER user 0 * :unknown
[2022-02-22T01:37:57 $irchost] NOTICE AUTH :*** Processing connection to 
$irchost
[2022-02-22T01:37:57 $irchost] NOTICE AUTH :*** Looking up your hostname...
NOTICE AUTH :*** Checking Ident
NOTICE AUTH :*** Couldn't look up your hostname
[2022-02-22T01:37:57 $irchost] NOTICE AUTH :*** No Ident response
:$irchost CAP * NAK :message-tags
:$irchost CAP * NAK :server-time
:$irchost CAP * NAK :batch
:$irchost CAP * NAK :message-ids
:$irchost CAP * NAK :invite-notify
[2022-02-22T01:37:58 $irchost] :$irchost CAP * NAK :sasl
[2022-02-22T01:37:59 $irchost] :$irchost CAP * ACK :multi-prefix
[2022-02-22T01:38:00 $irchost] :$irchost CAP * NAK :standard-replies
[2022-02-22T01:38:53 $irchost] ERROR :Closing Link: 10.22.16.11 
(Connection timed out)
[2022-02-22T01:38:53 $irchost] SENTINEL: #<process $irchost> "connection 
broken by remote peer
"


Since using this IRC server is pretty important for work, this made 
emacs-28 a non-starter for the moment; I switched back to emacs-27 and 
connected with debugging on, and it connected right away:

[2022-02-22T02:57:54 $irchost] NICK raeburn
[2022-02-22T02:57:54 $irchost] USER user 0 * :unknown
[2022-02-22T02:57:54 $irchost] NOTICE AUTH :*** Processing connection to 
$irchost
[2022-02-22T02:57:54 $irchost] NOTICE AUTH :*** Looking up your hostname...
NOTICE AUTH :*** Checking Ident
NOTICE AUTH :*** Couldn't look up your hostname
[2022-02-22T02:57:54 $irchost] NOTICE AUTH :*** No Ident response
:$irchost 001 raeburn :Welcome to the RHAT Internet Relay Chat Network 
raeburn


All I see that's different is the CAP requests, but ... ah, no "CAP END" 
has gotten sent for some reason, and apparently that's required before 
registration can complete on a server that understands capabilities. In 
the gnome log I sent earlier, it looks like all the requested 
capabilities were responded to, but still no "CAP END" was logged. Here, 
with my company server (running "ircd-ratbox-2.2.8") it seems to simply 
drop the connection quickly sometimes, and sometimes respond to the 
capabilities messages and then eventually time out.

Ken

bug#54087: 28.0.91; rcirc: irc.gnome reg timeout; reconnects after quit

[Ken Raeburn]

Aha! In the reply from irc.gnome.org, there's a space after the 
capability name. Hmm... actually, just the "ACK" ones, not the "NAK" 
ones. And the line splitting done in Lisp preserves it, associated with 
the capability name.

So rcirc-acked-capabilities accumulates names like "sasl ", and the 
names like "sasl" never get removed from rcirc-requested-capabilities. 
Since that list never becomes empty, we think we never finish the 
negotiation...

I'm not familiar enough with the IRC protocol to know if simply throwing 
away trailing whitespace always is a good solution, or if doing 
something specific for capability names is better, so I'll leave it at 
that for now.

bug#54087: 28.0.91; rcirc: irc.gnome reg timeout; reconnects after quit

[Ken Raeburn]

FWIW, I'm hacking around the bug for now by advising a function, and it 
seems to be working for both irc.gnome.org and my company IRC server. So 
the trailing space may have been the only issue blocking registration 
completion.


(defun kr-munge-args--rcirc-handler-CAP (all-args)
   (let ((cap-args (nth 2 all-args)))
     (while cap-args
       (if (string-match " +$" (car cap-args))
       (setcar cap-args (substring (car cap-args)
                       0 (match-beginning 0))))
       (setq cap-args (cdr cap-args))))
   all-args)

(if (version= emacs-version "28.0.91")
     (advice-add 'rcirc-handler-CAP
         :filter-args #'kr-munge-args--rcirc-handler-CAP))


So, to recap:

1) trailing space in CAP reply breaks registration

2) /quit triggers reconnect (if reconnection enabled)

3) name resolution failure not reported, just a vague connection failure

The parallel connection management seems to work nicely. (I could wish 
for separate threads so that when, say, Gnus ties up the main thread for 
several minutes trying to connect to a server that's down, the IRC 
servers don't decide my client has stopped responding. At least, I would 
hope other threads can run at that point.) I'll see if I run into any 
other problems in the next few days...

Ken