~emersion/soju#68: 
Clients do not rejoin irslackd channels on connect

With soju connected to a local https://github.com/adsr/irslackd instance, it does not join clients to channels when they reconnect.

A restart of irslackd causes soju to rejoin all clients once it itself connects to irslackd, but I assume this is caused by irslackd itself auto-joining all existing channels in that case.

Status
RESOLVED NOT_OUR_BUG
Submitter
~kennylevinsen
Assigned to
No-one
Submitted
5 months ago
Updated
5 months ago
Labels
No labels applied.

~emersion 5 months ago

Do you have -debug logs?

~kennylevinsen 5 months ago

Here are the connects (slightly filtered), which are unfortunately pretty unexciting:

# Restart of irslackd running at LOCAL_ADDR


Jun 11 16:49:55 localhost soju[7662]: 2020/06/11 16:49:55 upstream "LOCAL_ADDR": connecting to TLS server at address "LOCAL_ADDR"
Jun 11 16:49:55 localhost soju[7662]: 2020/06/11 16:49:55 upstream "LOCAL_ADDR": new connection
Jun 11 16:49:55 localhost soju[7662]: 2020/06/11 16:49:55 upstream "LOCAL_ADDR": sent: CAP LS 302
Jun 11 16:49:55 localhost soju[7662]: 2020/06/11 16:49:55 upstream "LOCAL_ADDR": sent: PASS XXXX
Jun 11 16:49:55 localhost soju[7662]: 2020/06/11 16:49:55 upstream "LOCAL_ADDR": sent: NICK kennylevinsen
Jun 11 16:49:55 localhost soju[7662]: 2020/06/11 16:49:55 upstream "LOCAL_ADDR": sent: USER kennylevinsen 0 * kennylevinsen
Jun 11 16:49:55 localhost soju[7662]: 2020/06/11 16:49:55 upstream "LOCAL_ADDR": received: :kennylevinsen NICK kl
Jun 11 16:49:55 localhost soju[7662]: 2020/06/11 16:49:55 upstream "LOCAL_ADDR": changed nick from "kennylevinsen" to "kl"
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": received: :kl JOIN #random
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": joined channel "#random"
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 downstream "MY_IP:54152": sent: :kl JOIN #random
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": sent: MODE #random
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 downstream "MY_IP:48560": sent: @time=2020-06-11T16:49:57.375Z :kl JOIN #random
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": received: :irslackd 332 kl #random :Non-work banter and water cooler conversation
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": received: :irslackd 353 kl = #random :kl XXXX
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": received: :irslackd 353 kl = #dev :kl XXXX
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": received: :irslackd MODE #random +
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 downstream "MY_IP:54152": sent: :irslackd MODE #random +
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 downstream "MY_IP:48560": sent: :irslackd MODE #random +
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": received: :kl JOIN #general
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": joined channel "#general"
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": received: :irslackd 332 kl #general :Company-wide announcements and work-based matters
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": received: :irslackd 353 kl = #general :kl XXXX
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 downstream "MY_IP:54152": sent: :kl JOIN #general
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": sent: MODE #general
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 downstream "MY_IP:48560": sent: @time=2020-06-11T16:49:57.424Z :kl JOIN #general
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": received: :irslackd MODE #general +
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 downstream "MY_IP:54152": sent: :irslackd MODE #general +
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 downstream "MY_IP:48560": sent: :irslackd MODE #general +
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": received: :kl JOIN #development
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": joined channel "#development"
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 downstream "MY_IP:54152": sent: :kl JOIN #development
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": sent: MODE #development
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 downstream "MY_IP:48560": sent: @time=2020-06-11T16:49:57.582Z :kl JOIN #development
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": received: :irslackd 353 kl = #development :kl XXXX
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 upstream "LOCAL_ADDR": received: :irslackd MODE #development +
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 downstream "MY_IP:54152": sent: :irslackd MODE #development +
Jun 11 16:49:57 localhost soju[7662]: 2020/06/11 16:49:57 downstream "MY_IP:48560": sent: :irslackd MODE #development +
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 upstream "LOCAL_ADDR": received: :irslackd 001 kl irslackd
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 upstream "LOCAL_ADDR": connection registered
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 downstream "MY_IP:54152": sent: :BouncerServ!BouncerServ@BouncerServ NOTICE kl :connected to REMOTE_NAME
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 upstream "LOCAL_ADDR": sent: JOIN #development,+irslackd ,
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 downstream "MY_IP:48560": sent: :MY_SOJU_INSTANCE CAP kl DEL multi-prefix
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 downstream "MY_IP:48560": sent: :MY_SOJU_INSTANCE CAP kl DEL away-notify
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 downstream "MY_IP:48560": sent: :BouncerServ!BouncerServ@BouncerServ NOTICE kl :connected to REMOTE_NAME
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 upstream "LOCAL_ADDR": received: :irslackd 376 kl :End of MOTD
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 upstream "LOCAL_ADDR": received: :kl JOIN +irslackd
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 upstream "LOCAL_ADDR": received: :irslackd 332 kl +irslackd :irslackd debug
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 upstream "LOCAL_ADDR": received: :irslackd 353 kl = +irslackd kl
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 upstream "LOCAL_ADDR": joined channel "+irslackd"
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 downstream "MY_IP:54152": sent: :kl!kennylevinsen@MY_IP JOIN +irslackd
Jun 11 16:49:58 localhost soju[7662]: 2020/06/11 16:49:58 upstream "LOCAL_ADDR": sent: MODE +irslackd

# Client reconnect

Jun 11 16:51:28 localhost soju[7662]: 2020/06/11 16:51:28 downstream "MY_IP:54208": new connection
Jun 11 16:51:28 localhost soju[7662]: 2020/06/11 16:51:28 downstream "MY_IP:54208": received: PASS XXXX
Jun 11 16:51:28 localhost soju[7662]: 2020/06/11 16:51:28 downstream "MY_IP:54208": received: NICK kennylevinsen
Jun 11 16:51:28 localhost soju[7662]: 2020/06/11 16:51:28 downstream "MY_IP:54208": received: USER kennylevinsen/REMOTE_NAME 0 * kennylevinsen/REMOTE_NAME
Jun 11 16:51:28 localhost soju[7662]: 2020/06/11 16:51:28 downstream "MY_IP:54208": registration complete for user "kennylevinsen"
Jun 11 16:51:28 localhost soju[7662]: 2020/06/11 16:51:28 downstream "MY_IP:54208": sent: :MY_SOJU_INSTANCE 001 kennylevinsen :Welcome to soju, kennylevinsen
Jun 11 16:51:28 localhost soju[7662]: 2020/06/11 16:51:28 downstream "MY_IP:54208": sent: :MY_SOJU_INSTANCE 002 kennylevinsen :Your host is MY_SOJU_INSTANCE
Jun 11 16:51:28 localhost soju[7662]: 2020/06/11 16:51:28 downstream "MY_IP:54208": sent: :MY_SOJU_INSTANCE 003 kennylevinsen :Who cares when the server was created?
Jun 11 16:51:28 localhost soju[7662]: 2020/06/11 16:51:28 downstream "MY_IP:54208": sent: :MY_SOJU_INSTANCE 004 kennylevinsen MY_SOJU_INSTANCE soju aiwroO OovaimnqpsrtklbeI
Jun 11 16:51:28 localhost soju[7662]: 2020/06/11 16:51:28 downstream "MY_IP:54208": sent: :MY_SOJU_INSTANCE 422 kennylevinsen :No MOTD
Jun 11 16:51:28 localhost soju[7662]: 2020/06/11 16:51:28 downstream "MY_IP:54208": sent: :kennylevinsen!kennylevinsen@MY_IP NICK kl

# <crickets from this connection, while my other connections join fine>

(If the full thing is needed, I can send it privately.)

~emersion 5 months ago

Okay, I see how this can happen. Maybe soju sends the channels from the DB when a client connects, instead of sending the channels of the upstream connection.

~kennylevinsen REPORTED NOT_OUR_BUG 5 months ago

Hmm, looking further into it, it would appear that the issue is a non-compliant server.

irslackd does not seem to send 366 ENDOFNAMES after the name commands. This means that the "complete" flag remain false for these channels. If clients are connected when upstream connects, the join messages are forwarded, but when clients connect later, soju skips the "incomplete" channels.

Register here or Log in to comment, or comment via email.