• Willkommen im Linux Club - dem deutschsprachigen Supportforum für GNU/Linux. Registriere dich kostenlos, um alle Inhalte zu sehen und Fragen zu stellen.

[Erledigt] Prosody: connection-timeout bei manchen S2S-Verbindungen

gehrke

Administrator
Teammitglied
Ich habe scheinbar seit einem größeren Upgrade eines Servers mit CentOS 8 Probleme, dass Prosody bei manchen S2S-Verbindungen (XMPP) scheitert - aber nicht bei allen.

Fehlerbild:
Code:
# grep --text 's2sout5621b4926660' /var/log/prosody/prosody.log
Apr 30 06:40:08 s2sout5621b4926660	info	Outgoing s2s stream [xxx]->conference.gajim.org closed: connection-timeout
Apr 30 06:40:08 s2sout5621b4926660	info	Sending error replies for 1 queued stanzas because of failed outgoing connection to conference.gajim.org
Aus Sicht des Users zeigen sich die betroffenen Räume ohne Inhalt und Benutzer.

Upgrade Prosody:
Code:
    Upgrade  prosody-0.11.5-1.el8.x86_64                 @epel
    Upgraded prosody-0.11.4-1.el8.x86_64                 @@System

Das fragliche Upgrade von Sonntag im Ganzen:
Code:
# dnf history info 65 
Failed to set locale, defaulting to C.UTF-8
Modular dependency problems:

 Problem 1: conflicting requests
  - nothing provides module(perl:5.26) needed by module perl-DBI:1.641:8010020191113222731:16b3ab4d-0.x86_64
 Problem 2: conflicting requests
  - nothing provides module(nginx) needed by module php:7.2:8010020200220193032:2430b045-0.x86_64
Transaction ID : 65
Begin time     : Sun Apr 26 08:24:06 2020
Begin rpmdb    : 775:c89f9d35ece64d0c26621ee6807759385912e8e2
End time       : Sun Apr 26 08:27:02 2020 (176 seconds)
End rpmdb      : 775:f178c2cafcfc6447e709663bc57f7d6d90d88927
User           : root <root>
Return-Code    : Success
Releasever     : 8
Command Line   : upgrade
Packages Altered:
    Install  kernel-4.18.0-193.10.el8.x86_64             @Stream-BaseOS
    Install  kernel-core-4.18.0-193.10.el8.x86_64        @Stream-BaseOS
    Install  kernel-debug-devel-4.18.0-193.10.el8.x86_64 @Stream-BaseOS
    Install  kernel-devel-4.18.0-193.10.el8.x86_64       @Stream-BaseOS
    Install  kernel-modules-4.18.0-193.10.el8.x86_64     @Stream-BaseOS
    Upgrade  kernel-headers-4.18.0-193.10.el8.x86_64     @Stream-BaseOS
    Upgraded kernel-headers-4.18.0-187.el8.x86_64        @@System
    Upgrade  kernel-tools-4.18.0-193.10.el8.x86_64       @Stream-BaseOS
    Upgraded kernel-tools-4.18.0-187.el8.x86_64          @@System
    Upgrade  kernel-tools-libs-4.18.0-193.10.el8.x86_64  @Stream-BaseOS
    Upgraded kernel-tools-libs-4.18.0-187.el8.x86_64     @@System
    Upgrade  python3-perf-4.18.0-193.10.el8.x86_64       @Stream-BaseOS
    Upgraded python3-perf-4.18.0-187.el8.x86_64          @@System
    Upgrade  python3-ply-3.9-8.el8.noarch                @Stream-BaseOS
    Upgraded python3-ply-3.9-7.el8.noarch                @@System
    Upgrade  prosody-0.11.5-1.el8.x86_64                 @epel
    Upgraded prosody-0.11.4-1.el8.x86_64                 @@System
    Removed  kernel-4.18.0-168.el8.x86_64                @@System
    Removed  kernel-core-4.18.0-168.el8.x86_64           @@System
    Removed  kernel-debug-devel-4.18.0-168.el8.x86_64    @@System
    Removed  kernel-devel-4.18.0-168.el8.x86_64          @@System
    Removed  kernel-modules-4.18.0-168.el8.x86_64        @@System
Wegen Kernel-Update wurde das System gebootet.

BTW: Neben Prosody läuft auf dem System auch noch eine Instanz von Synapse. Die zeigt bislang keine Probleme.

Offensichtlich relevante Fehlermeldungen beim Start von Prosody sehe ich nicht.

TNX
 
OP
gehrke

gehrke

Administrator
Teammitglied
Stichprobenartig die Erreichbarkeit der betreffenden Dienste von dem Host aus per telnet geprüft. Grundsätzlich scheinen die erreichbar, sowohl per IPv4 als auch IPv6. Die legen nur irgendwann auf (timeout), wenn nix mehr kommt, was ja am test-Setup mit telnet liegt.

Code:
# telnet conference.conversations.im 5269
Trying 2a00:1828:2000:215::44...
Connected to conference.conversations.im.
Escape character is '^]'.
Connection closed by foreign host.

Code:
# telnet conference.gajim.org 5269
Trying 212.129.3.231...
Connected to conference.gajim.org.
Escape character is '^]'.
<?xml version='1.0'?><stream:stream xmlns='jabber:server' xml:lang='en' xmlns:db='jabber:server:dialback' xmlns:stream='http://etherx.jabber.org/streams' from='' to=''><stream:error><connection-timeout xmlns='urn:ietf:params:xml:ns:xmpp-streams'/></stream:error></stream:stream>Connection closed by foreign host.

Code:
# telnet conference.jabber.ccc.de 5269
Trying 2a02:1b8:10:31::229...
Connected to conference.jabber.ccc.de.
Escape character is '^]'.
Connection closed by foreign host.
 
gehrke schrieb:
Ich habe scheinbar seit einem größeren Upgrade eines Servers mit CentOS 8 Probleme, dass Prosody bei manchen S2S-Verbindungen (XMPP) scheitert - aber nicht bei allen.

Fehlerbild:
Code:
# grep --text 's2sout5621b4926660' /var/log/prosody/prosody.log
Apr 30 06:40:08 s2sout5621b4926660	info	Outgoing s2s stream [xxx]->conference.gajim.org closed: connection-timeout
Apr 30 06:40:08 s2sout5621b4926660	info	Sending error replies for 1 queued stanzas because of failed outgoing connection to conference.gajim.org
Die nächste(n) Zeile(n) könnten für eine Fehlersuche hilfreich sein.
Siehe dazu das LUA plugin: function bounce_sendq()
https://github.com/bjc/prosody/tree/master/plugins/mod_s2s
 
OP
gehrke

gehrke

Administrator
Teammitglied
Gräfin Klara schrieb:
Die nächste(n) Zeile(n) könnten für eine Fehlersuche hilfreich sein.
Sorry, war durch sinnfreies Brötchenverdienen abgelenkt. Der Tag hat mich geschlaucht, daher hier nur die angesprochenen Logeinträge ohne viel Inspiration. Vielleicht geht morgen mehr...
Dank schonmal für Deine Antwort.

Viel geben die folgenden Einträge auf den ersten Blick nicht her.
Code:
Apr 30 06:48:14 s2sout5621b4889630      info    Session closed by remote with error: connection-timeout (Idle connection)
Apr 30 06:48:14 s2sout5621b4889630      info    Outgoing s2s stream [xxx]->das-labor.org closed: connection-timeout (Idle connection)
Apr 30 06:48:23 s2sout5621b4b2c3f0      info    Session closed by remote with error: connection-timeout (Idle connection)
Apr 30 06:48:23 s2sout5621b4b2c3f0      info    Outgoing s2s stream [...]->conference.conversations.im closed: connection-timeout (Idle connection)
Apr 30 06:53:07 adns    warn    DNS socket for 213.133.99.99 disconnected: read timeout
Apr 30 07:04:09 s2sout5621b4f80df0      info    Failed in all attempts to connect to conference.c3re.de
Apr 30 07:04:09 s2sout5621b4f80df0      info    Sending error replies for 1 queued stanzas because of failed outgoing connection to conference.c3re.de
Apr 30 07:04:13 s2sout5621b4f956c0      info    Failed in all attempts to connect to conference.c3re.de
Apr 30 07:04:13 s2sout5621b4f956c0      info    Sending error replies for 1 queued stanzas because of failed outgoing connection to conference.c3re.de
Apr 30 07:34:06 s2sout5621b4d03c70      info    Failed in all attempts to connect to c3re.de
 
gehrke schrieb:
Viel geben die folgenden Einträge auf den ersten Blick nicht her.
Code:
Apr 30 06:48:14 s2sout5621b4889630      info    Session closed by remote with error: connection-timeout (Idle connection)
..
Apr 30 06:53:07 adns    warn    DNS socket for 213.133.99.99 disconnected: read timeout
..
Apr 30 07:04:09 s2sout5621b4f80df0      info    Failed in all attempts to connect to conference.c3re.de
Alle sockets oder jene sockets im Zusammenhang mit prosody, werden zu bestimmter Zeit getrennt.
Ich gehe davon aus, dass die Warnung von adns auch im prosody.log steht.
adns ist ein DNS resolver library, also ein DNS client, der im gezeigten Fall seine Verbindung zu einem DNS Server von hetzner.net verliert.
Im Grunde zur selben Zeit, wie auch die sockets von prosody flöten gehen.
adns hat keinen eigenen "socket Mechanismus", prosody muß adns diesen Mechanismus zur Verfügung stellen, d.h.
diese adns Wanung betrifft ebenfalls einen prosody socket (falls diese adns Warnung in prosody.log steht)

Deshalb würde ich an deiner Stelle prosody neu installieren. prosody ist ja nichts anderes als ein script und solche scripts reagieren
empfindlich auf Systemänderungen, die dein Update ja mit sich gebracht haben. Nach einer Neuinstallation könnte man viele
Gründe dieses Problems ausschliessen oder das Problem erledigt sich von selbst.
 
OP
gehrke

gehrke

Administrator
Teammitglied
TNX

Ich gehe davon aus, dass die Warnung von adns auch im prosody.log steht.
Ja, das ist korrekt.

Habe mal stumpf neu installiert, weil es schnell geht, mangels Alternativen und um $Dinge verifizieren oder ausschließen zu können.

Code:
 1002  2020-05-01 11:36:23 systemctl stop prosody.service
 1003  2020-05-01 11:36:37 dnf remove prosody
 1004  2020-05-01 11:37:14 dnf install prosody
 1005  2020-05-01 11:38:08 systemctl enable prosody.service
 1006  2020-05-01 11:39:40 systemctl start prosody.service; tail -f /var/log/prosody/prosody.{err,log}

Leider stellt sich die Situation danach nicht anders dar als zuvor.
 
gehrke schrieb:
Leider stellt sich die Situation danach nicht anders dar als zuvor.
Die für das Problem relevanten LUA scripts sind hier
https://github.com/bjc/prosody/tree/master/net
(Da ist auch dieses adns zu finden)
Alle diese scripts unterstützen ein debug_log.
Hast du das schon eingeschalten? Könnte hilfreich sein.
 
OP
gehrke

gehrke

Administrator
Teammitglied
Menno, Du beschämst mich. Ja, Debug anschalten wär mal 'ne echt neue Idee. :zensur:

Habe eine Session zu einem der Beispiele willkürlich rausgegriffen:
Code:
# grep --text 's2sout559acf4f72d0' /var/log/prosody/prosody.log
May 01 17:28:00 s2sout559acf4f72d0	debug	First attempt to connect to conference.c3re.de, starting with SRV lookup...
May 01 17:28:00 s2sout559acf4f72d0	debug	trying to send over unauthed s2sout to conference.c3re.de
May 01 17:28:00 s2sout559acf4f72d0	debug	stanza [iq] queued 
May 01 17:28:00 s2sout559acf4f72d0	debug	conference.c3re.de has no SRV records, falling back to A/AAAA
May 01 17:28:00 s2sout559acf4f72d0	debug	DNS reply for conference.c3re.de gives us 116.203.223.175
May 01 17:28:00 s2sout559acf4f72d0	debug	Beginning new connection attempt to conference.c3re.de ([116.203.223.175]:5269)
May 01 17:28:00 s2sout559acf4f72d0	debug	Connection attempt in progress...
May 01 17:28:00 s2sout559acf4f72d0	debug	s2s connection attempt failed: connection refused
May 01 17:28:00 s2sout559acf4f72d0	debug	Out of IP addresses, trying next SRV record (if any)
May 01 17:28:00 s2sout559acf4f72d0	info	Failed in all attempts to connect to conference.c3re.de
May 01 17:28:00 s2sout559acf4f72d0	debug	No other records to try for conference.c3re.de - destroying
May 01 17:28:00 s2sout559acf4f72d0	debug	Destroying outgoing session <xxx>->conference.c3re.de: Connecting failed: connection refused
May 01 17:28:00 s2sout559acf4f72d0	info	Sending error replies for 2 queued stanzas because of failed outgoing connection to conference.c3re.de
May 01 17:28:00 s2sout559acf4f72d0	debug	s2s disconnected: <nil>-><nil> (connection refused)

Das sieht bei den anderen problematisch Systemen stichpunktartig identisch aus:
Code:
# grep --text 'No other records to try for ' /var/log/prosody/prosody.log
May 01 17:28:00 s2sout559acf4beb60	debug	No other records to try for c3re.de - destroying
May 01 17:28:00 s2sout559acf4f72d0	debug	No other records to try for conference.c3re.de - destroying
May 01 17:28:00 s2sout559acf5319e0	debug	No other records to try for conference.das-labor.de - destroying
May 01 17:28:00 s2sout559acf4ce920	debug	No other records to try for stablerock.de - destroying

Einige davon lassen sich auf dem System via DNS nach IPv4 oder IPv6 auflösen, 'conference.das-labor.de' nicht. Aber solange das nicht bei allen der Fall ist, erscheint mir das als Ursache nicht plausibel.

Erschwerend kommt hinzu, dass ich nur von einem davon aufgrund aktiver Nutzung verlässlich sagen kann, dass das vor meiner Migration am Sonntag tatsächlich funktioniert hat. Und die haben just an dem Wochenende ebenfalls eine Migration vorgenommen. Könnte also sein, dass das Problem gar nicht auf meiner Seite liegt...
 
OP
gehrke

gehrke

Administrator
Teammitglied
Gegenbeispiel, wo die Logs via S2S gut aussehen und auch der MUC in meinem Client lebendig ist:
Code:
conference.gajim.org
 
Nun sieht man doch um einiges besser.

gehrke schrieb:
Könnte also sein, dass das Problem gar nicht auf meiner Seite liegt...
Da bin ich mir nicht so sicher.
Die relevanten Zeilen interpretiere ich folgend:
Code:
...
May 01 17:28:00 s2sout559acf4f72d0	debug	Beginning new connection attempt to conference.c3re.de ([116.203.223.175]:5269)
...
May 01 17:28:00 s2sout559acf4f72d0	debug	s2s connection attempt failed: connection refused
..
Auf deiner Seite wird alles versucht, ich kann keinen Fehler in den Logs erkennen, trotzdem geht die Verbindung schief.
Wenn man sich die scripts ansieht, dann kommt bei z.B, Gegenstelle nicht vorhanden, server läuft nicht, etc. immer
connection timed out.
Aber in diesem Fall wurde die Verbindung erfolgreich aufgebaut, der socket ist vorhanden, der Server weist dich aber zurück.
Das sieht nach einem Berechtigungsproblem aus oder nach einer firewall mit der rule "Reject"
Beides hat zum Resultat "connection refused". So nach einem flotten Blick in den LUA scripts zu sehen.
 
OP
gehrke

gehrke

Administrator
Teammitglied
Code:
# setenforce 0
# systemctl stop firewalld.service
Keine Änderung des Verhaltens. Ich wüsste nicht, wo ich auf meiner Seite noch Ansatzpunkte habe.
 
.
Da ist ja kein Listener auf der anderen Seite
Code:
# ncat -vv conference.gajim.org 5269
ok, connected
Code:
# blah blah
<?xml version='1.0'?><stream:stream xmlns:db='jabber:server:dialback' to='' xm .....
# Ctrl/c
ok

Code:
# ncat -vv 116.203.223.175 5269
refused. Da ist niemand. Corona?
 
OP
gehrke

gehrke

Administrator
Teammitglied
Ja. Scheinbar ist die Gegenseite kaputtmigriert, nicht meine. Ich versuch da mal jemanden vom NOC zu fassen.

Bei den anderen MUC's prüfe ich mal die Logs, ob die nicht vorher auch schon kaputt waren.

@Gräfin Klara: TNX
 
OP
gehrke

gehrke

Administrator
Teammitglied
Im letzten Fall habe ich Feedback vom Anbieter erhalten. Der Dienst wurde eingestellt, tatsächlich zufällig zeitgleich mit meinen Aktivitäten.

Insofern ist die Sache plausibel, kein Problem auf meiner Seite. Ich setze das hier auf [Erledigt].

Dank nochmals an Gräfin Klara für die hilfreiche Mitarbeit.
 
Oben