[Spacewalk-list] osa-dispatcher dies shortly after starting [SEC=UNOFFICIAL]

[Robert Paschedag]

Am 19. September 2017 02:15:10 MESZ schrieb Jonathan Payne <Jonathan.Payne at franklincovey.com>:
>Additional debug shows the following in osa-dispatcher:
>
><-- <iq type='result' id='iq-request-0848dd-19'><query xmlns =
>'jabber:iq:roster' ><item jid='osad-b6150a2570 at SPACEWALKSERVER'
>subscription='to' /><item jid='osad-2bf4ba6a94 at SPACEWALKSERVER'
>subscription='to' /><item jid='osad-7bad8b8265 at SPACEWALKSERVER'
>subscription='to' /><item jid='osad-e1dda4dc96 at SPACEWALKSERVER'
>subscription='to' /><item jid='osad-5763abe98f at SPACEWALKSERVER'
>subscription='to' /><item jid='osad-d042f17bd6 at SPACEWALKSERVER'
>subscription='to' /><item jid='osad-aa8d364683 at SPACEWALKSERVER'
>subscription='to' /></query></iq>
>
><-- <iq to='rhn-dispatcher-sat at SPACEWALKSERVER/superclient' type='set'
>id='texv6hlicjon2s1ele1cst0zq28ux8krmimtz8bc'><query xmlns =
>'jabber:iq:roster' ><item jid='osad-2bf4ba6a94 at SPACEWALKSERVER'
>subscription='both' /></query></iq>
>
>--> <iq type='get' id='iq-request-0848dd-20'><query xmlns =
>'jabber:iq:roster'  /></iq>
>
><-- <iq to='rhn-dispatcher-sat at SPACEWALKSERVER/superclient' type='set'
>id='r00us18egaq83r8ttgorp9ibr54qdg35g3z957nl'><query xmlns =
>'jabber:iq:roster' ><item jid='osad-d042f17bd6 at SPACEWALKSERVER'
>subscription='both' /></query></iq>
>
><-- <iq to='rhn-dispatcher-sat at SPACEWALKSERVER/superclient' type='set'
>id='rvh4518kr3dw1cj29f9ez20xo92ex6np14u762rx'><query xmlns =
>'jabber:iq:roster' ><item jid='osad-7bad8b8265 at SPACEWALKSERVER'
>subscription='both' /></query></iq>
>
><-- <iq to='rhn-dispatcher-sat at SPACEWALKSERVER/superclient' type='set'
>id='65u7heaquj4tl5raftod0c22gw9nz1l56gdounfp'><query xmlns =
>'jabber:iq:roster' ><item jid='osad-e1dda4dc96 at SPACEWALKSERVER'
>subscription='both' /></query></iq>
>
><-- <iq to='rhn-dispatcher-sat at SPACEWALKSERVER/superclient' type='set'
>id='jqxob49tlib3dzrn04townj807aoyihh8e5kjfd4'><query xmlns =
>'jabber:iq:roster' ><item jid='osad-5763abe98f at SPACEWALKSERVER'
>subscription='both' /></query></iq>
>
><-- <presence from='osad-b6150a2570 at SPACEWALKSERVER' type='subscribe'
>id='presence-088791-33'
>to='rhn-dispatcher-sat at SPACEWALKSERVER/superclient' />
>
>--> <presence to='osad-b6150a2570 at SPACEWALKSERVER' type='subscribed'
>id='presence-088791-33' />
>
><-- <iq type='result' id='iq-request-0848dd-20'><query xmlns =
>'jabber:iq:roster' ><item jid='osad-b6150a2570 at SPACEWALKSERVER'
>subscription='to' /><item jid='osad-2bf4ba6a94 at SPACEWALKSERVER'
>subscription='both' /><item jid='osad-7bad8b8265 at SPACEWALKSERVER'
>subscription='both' /><item jid='osad-e1dda4dc96 at SPACEWALKSERVER'
>subscription='both' /><item jid='osad-5763abe98f at SPACEWALKSERVER'
>subscription='both' /><item jid='osad-d042f17bd6 at SPACEWALKSERVER'
>subscription='both' /><item jid='osad-aa8d364683 at SPACEWALKSERVER'
>subscription='to' /></query></iq>
>
><-- <iq to='rhn-dispatcher-sat at SPACEWALKSERVER/superclient' type='set'
>id='l3ey7ycp9eljg1wmwxypgealw91g1cmng0lozyd8'><query xmlns =
>'jabber:iq:roster' ><item jid='osad-b6150a2570 at SPACEWALKSERVER'
>subscription='both' /></query></iq>
>
>--> <iq type='get' id='iq-request-0848dd-21'><query xmlns =
>'jabber:iq:roster'  /></iq>
>
><-- <iq type='result' id='iq-request-0848dd-21'><query xmlns =
>'jabber:iq:roster' ><item jid='osad-b6150a2570 at SPACEWALKSERVER'
>subscription='both' /><item jid='osad-2bf4ba6a94 at SPACEWALKSERVER'
>subscription='both' /><item jid='osad-7bad8b8265 at SPACEWALKSERVER'
>subscription='both' /><item jid='osad-e1dda4dc96 at SPACEWALKSERVER'
>subscription='both' /><item jid='osad-5763abe98f at SPACEWALKSERVER'
>subscription='both' /><item jid='osad-d042f17bd6 at SPACEWALKSERVER'
>subscription='both' /><item jid='osad-aa8d364683 at SPACEWALKSERVER'
>subscription='to' /></query></iq>
>
>--> <iq type='get' id='iq-request-0848dd-22'><query xmlns =
>'jabber:iq:roster'  /></iq>
>
><-- <presence from='osad-6a13fc5ea7 at SPACEWALKSERVER' type='subscribe'
>id='presence-6458c3-47'
>to='rhn-dispatcher-sat at SPACEWALKSERVER/superclient' />
>
>--> <presence to='osad-6a13fc5ea7 at SPACEWALKSERVER' type='subscribed'
>id='presence-6458c3-47' />
>
>Spacewalk 18579 2017/09/18 17:49:47 -06:00: ('Error caught:',)
>
>ERROR: unhandled exception occurred: (can't write str to text stream).
>
>
>
>I don’t see any errors in /var/log/messages relating to jabberd, just
>the usual:
>
>Sep 18 17:42:52 spacewalk2 jabberd/sm[18460]: [SPACEWALKSERVER]
>configured
>Sep 18 17:42:52 spacewalk2 jabberd/sm[18460]: attempting connection to
>router at ::1, port=5347
>Sep 18 17:42:52 spacewalk2 jabberd/router[18452]: [::1, port=34632]
>connect
>Sep 18 17:42:52 spacewalk2 jabberd/router[18452]: [::1, port=34632]
>authenticated as jabberd at jabberd-router
>Sep 18 17:42:52 spacewalk2 jabberd/sm[18460]: connection to router
>established
>Sep 18 17:42:52 spacewalk2 jabberd/router[18452]: [SPACEWALKSERVER]
>online (bound to ::1, port 34632)
>Sep 18 17:42:52 spacewalk2 jabberd/c2s[18468]: modules search path:
>/usr/lib64/jabberd
>Sep 18 17:42:52 spacewalk2 jabberd/c2s[18468]: loading 'db' authreg
>module
>Sep 18 17:42:52 spacewalk2 jabberd/c2s[18468]: initialized auth module
>'db'
>Sep 18 17:42:52 spacewalk2 jabberd/c2s[18468]: starting up
>Sep 18 17:42:52 spacewalk2 jabberd/c2s[18468]: process id is 18468,
>written to /var/lib/jabberd/pid/c2s.pid
>Sep 18 17:42:52 spacewalk2 jabberd/sm[18460]: SPACEWALKSERVER ready for
>sessions
>Sep 18 17:42:52 spacewalk2 jabberd/s2s[18476]: starting up (interval=3,
>queue=60, keepalive=0, idle=86400)
>Sep 18 17:42:52 spacewalk2 jabberd/s2s[18476]: process id is 18476,
>written to /var/lib/jabberd/pid/s2s.pid
>Sep 18 17:42:52 spacewalk2 jabberd/s2s[18476]: attempting connection to
>router at ::1, port=5347
>Sep 18 17:42:52 spacewalk2 jabberd/router[18452]: [::1, port=34634]
>connect
>Sep 18 17:42:52 spacewalk2 jabberd/router[18452]: [::1, port=34634]
>authenticated as jabberd at jabberd-router
>Sep 18 17:42:52 spacewalk2 jabberd/s2s[18476]: connection to router
>established
>Sep 18 17:42:52 spacewalk2 jabberd/router[18452]: [s2s] set as default
>route
>Sep 18 17:42:52 spacewalk2 jabberd/router[18452]: [s2s] online (bound
>to ::1, port 34634)
>Sep 18 17:42:53 spacewalk2 jabberd/c2s[18468]: [SPACEWALKSERVER]
>configured; realm=, authreg=db, registration enabled, using
>PEM:/etc/pki/spacewalk/jabberd/server.pem
>Sep 18 17:42:53 spacewalk2 jabberd/c2s[18468]: attempting connection to
>router at ::1, port=5347
>Sep 18 17:42:53 spacewalk2 jabberd/router[18452]: [::1, port=34636]
>connect
>Sep 18 17:42:53 spacewalk2 jabberd/router[18452]: [::1, port=34636]
>authenticated as jabberd at jabberd-router
>Sep 18 17:42:53 spacewalk2 jabberd/c2s[18468]: connection to router
>established
>Sep 18 17:42:53 spacewalk2 jabberd/router[18452]: [c2s] online (bound
>to ::1, port 34636)
>Sep 18 17:42:53 spacewalk2 jabberd/s2s[18476]: [::, port=5269]
>listening for connections
>Sep 18 17:42:53 spacewalk2 jabberd/s2s[18476]: ready for connections
>Sep 18 17:42:53 spacewalk2 jabberd/c2s[18468]: [::, port=5222]
>listening for connections
>Sep 18 17:42:53 spacewalk2 jabberd/c2s[18468]: ready for connections
>Sep 18 17:42:53 spacewalk2 jabberd/c2s[18468]: [7] [::ffff:IPADDRESS,
>port=38292] connect
>Sep 18 17:42:53 spacewalk2 jabberd/c2s[18468]: [7] [::ffff:IPADDRESS,
>port=38292] disconnect jid=unbound, packets: 0, bytes: 163
>Sep 18 17:42:54 spacewalk2 jabberd/c2s[18468]: [7]
>[::ffff:192.168.0.85, port=58130] connect
>Sep 18 17:42:54 spacewalk2 jabberd/c2s[18468]: [7] created user:
>user=osad-8041749890; realm=
>Sep 18 17:42:54 spacewalk2 jabberd/c2s[18468]: [7] registration
>succeeded, requesting user creation:
>jid=osad-8041749890 at SPACEWALKSERVER
>Sep 18 17:42:54 spacewalk2 jabberd/sm[18460]: created user:
>jid=osad-8041749890 at SPACEWALKSERVER
>Sep 18 17:42:54 spacewalk2 jabberd/c2s[18468]: [7] traditional.digest
>authentication succeeded: osad-8041749890@/osad
>::ffff:192.168.0.85:58130 TLS
>Sep 18 17:42:54 spacewalk2 jabberd/c2s[18468]: [7] requesting session:
>jid=osad-8041749890 at SPACEWALKSERVER/osad
>Sep 18 17:42:54 spacewalk2 jabberd/sm[18460]: session started:
>jid=osad-8041749890 at SPACEWALKSERVER/osad
>Sep 18 17:42:55 spacewalk2 jabberd/c2s[18468]: [10]
>[::ffff:192.168.0.204, port=37242] connect
>Sep 18 17:42:55 spacewalk2 jabberd/c2s[18468]: [10] created user:
>user=osad-cdee74d3cf; realm=
>Sep 18 17:42:55 spacewalk2 jabberd/c2s[18468]: [10] registration
>succeeded, requesting user creation:
>jid=osad-cdee74d3cf at SPACEWALKSERVER
>Sep 18 17:42:55 spacewalk2 jabberd/sm[18460]: created user:
>jid=osad-cdee74d3cf at SPACEWALKSERVER
>Sep 18 17:42:55 spacewalk2 jabberd/c2s[18468]: [10] traditional.digest
>authentication succeeded: osad-cdee74d3cf@/osad
>::ffff:192.168.0.204:37242 TLS
>Sep 18 17:42:55 spacewalk2 jabberd/c2s[18468]: [10] requesting session:
>jid=osad-cdee74d3cf at SPACEWALKSERVER/osad
>Sep 18 17:42:55 spacewalk2 jabberd/sm[18460]: session started:
>jid=osad-cdee74d3cf at SPACEWALKSERVER/osad
>Sep 18 17:43:00 spacewalk2 jabberd/c2s[18468]: [11]
>[::ffff:192.168.0.149, port=33206] connect
>Sep 18 17:43:00 spacewalk2 jabberd/c2s[18468]: [11] created user:
>user=osad-b4a12af2f9; realm=
>Sep 18 17:43:00 spacewalk2 jabberd/c2s[18468]: [11] registration
>succeeded, requesting user creation:
>jid=osad-b4a12af2f9 at SPACEWALKSERVER
>Sep 18 17:43:00 spacewalk2 jabberd/sm[18460]: created user:
>jid=osad-b4a12af2f9 at SPACEWALKSERVER
>
>From: <spacewalk-list-bounces at redhat.com> on behalf of Andrew Bergman
><Andrew.Bergman at bom.gov.au>
>Reply-To: "spacewalk-list at redhat.com" <spacewalk-list at redhat.com>
>Date: Monday, September 18, 2017 at 5:44 PM
>To: "spacewalk-list at redhat.com" <spacewalk-list at redhat.com>
>Subject: Re: [Spacewalk-list] osa-dispatcher dies shortly after
>starting [SEC=UNOFFICIAL]
>
>Run osa-dispatcher from the command line:
>
>osa-dispatcher -N –vvvvvvvvvvvvvvv
>
>What do you get?
>
>Each v represents 1 debug setting.  So put maybe 10 in.
>
>Regards
>
>Andrew Bergman
>
>From: spacewalk-list-bounces at redhat.com
>[mailto:spacewalk-list-bounces at redhat.com] On Behalf Of Jonathan Payne
>Sent: Tuesday, 19 September 2017 6:22 AM
>To: spacewalk-list at redhat.com
>Subject: [Spacewalk-list] osa-dispatcher dies shortly after starting
>
>Hoping for some assistance here, as I’ve been banging my head against
>the wall on this issue.
>
>I just upgraded from Spacewalk 2.2 to 2.6, and now osa-dispatcher is
>dying with no information on the error, and the status just saying the
>process is dead but the pid file still exists.
>
>LOG at Debug level 7:
>2017/09/18 11:33:25 -06:00 12686 0.0.0.0:
>rhnSQL/driver_postgresql.convert_named_query_params('Converting query
>for PostgreSQL: select * from rhnPushClient where jabber_id = :p1',)
>2017/09/18 11:33:25 -06:00 12686 0.0.0.0:
>rhnSQL/driver_postgresql.convert_named_query_params('New query: select
>* from rhnPushClient where jabber_id = %(p1)s',)
>2017/09/18 11:33:25 -06:00 12686 0.0.0.0:
>rhnSQL/driver_postgresql._execute_wrapper('Executing SQL: "select *
>from rhnPushClient where jabber_id = %(p1)s" with bind params: {p1:
>osad-6d4dfeb426 at SPACEWALKSERVERNAME/osad}',)
>2017/09/18 11:33:25 -06:00 12686 0.0.0.0: osad/jabber_lib.main('ERROR',
>'Error caught:')
>
>
>                service osa-dispatcher status
>osa-dispatcher dead but pid file exists
>
>
>
>I have checked my jabberd xml files, and they appear to be setup
>correctly. One thing I found odd is that the server name shows up twice
>in the sm.xml. I changed the <id> under <sm> back to the default of sm,
>but that didnt' fix the issue.
>
>                /etc/jabberd/sm.xml
><sm>
>  <!-- Our ID on the network (default: sm) -->
>  <id>SPACEWALKSERVERNAME</id>
>
><!-- Local network configuration -->
>  <local>
>    <id>SPACEWALKSERVERNAME </id>
>    <!-- Who we identify ourselves as.
>         Users will have this as the domain part of their JID.
>         If you want your server to be accessible from other
>         Jabber servers, this IDs must be FQDN resolvable by DNSes.
>         If not set, the SM id is used. -->
>    <id>localhost.localdomain</id>
>    <!--
>    <id>vhost1.localdomain</id>
>    <id>vhost2.localdomain</id>
>    -->
>
>                grep jabber /etc/rhn/rhn.conf
>                             server.jabber_server = SPACEWALKSERVERNAME
>                     osa-dispatcher.jabber_server = SPACEWALKSERVERNAME
>
>                ll /etc/jabberd/*.xml
>-rw-r-----. 1 jabber jabber  25K Sep 17 20:20 /etc/jabberd/c2s.xml
>-rw-r-----. 1 jabber jabber 2.0K Jul 14 02:10
>/etc/jabberd/router-filter.xml
>-rw-r-----. 1 jabber jabber  258 Jul 14 02:10
>/etc/jabberd/router-users.xml
>-rw-r-----. 1 jabber jabber 6.9K Sep 17 20:20 /etc/jabberd/router.xml
>-rw-r-----. 1 jabber jabber  12K Sep 17 20:20 /etc/jabberd/s2s.xml
>-rw-r-----. 1 jabber jabber  31K Sep 18 11:20 /etc/jabberd/sm.xml
>
>
>
>
>I also checked the SSL certs to verify that they are correct and that
>the certificate matches the hostname in /etc/jabberd/c2s.xml. I have
>verified permissions, as well. Hostname is in the hosts file.
>
>md5sum /etc/pki/spacewalk/jabberd/server.pem /root/ssl-build/
>SPACEWALKSERVERNAME server.pem
>eda16d799aefba2acc5a5b4b278227ac  /etc/pki/ SPACEWALKSERVERNAME
>jabberd/server.pem
>eda16d799aefba2acc5a5b4b278227ac  /root/ssl-build/ SPACEWALKSERVERNAME
>server.pem
>
>ll /etc/pki/spacewalk/jabberd/
>-rw-------. 1 jabber jabber 7.2K Mar  4  2014 server.pem
>
>md5sum /root/ssl-build/RHN-ORG-TRUSTED-SSL-CERT
>/var/www/html/pub/RHN-ORG-TRUSTED-SSL-CERT
>4a3fa3d648a87aee70151dd6ee030c9b 
>/root/ssl-build/RHN-ORG-TRUSTED-SSL-CERT
>4a3fa3d648a87aee70151dd6ee030c9b 
>/var/www/html/pub/RHN-ORG-TRUSTED-SSL-CERT
>
>grep CN= $(grep spacewalk.crt /etc/httpd/conf.d/ssl.conf | cut -f 2 -d'
>') | grep Subject
>                OU= SPACEWALKSERVERNAME, CN= SPACEWALKSERVERNAME
>
>
>grep require-starttls /etc/jabberd/c2s.xml | grep pemfile
><id require-starttls="false"
>pemfile="/etc/pki/spacewalk/jabberd/server.pem" realm=""
>register-enable="true">SPACEWALKSERVERNAME</id>
>
>grep CN= /etc/pki/spacewalk/jabberd/server.pem | grep Subject
>                OU= SPACEWALKSERVERNAME, CN= SPACEWALKSERVERNAME
>
>grep "osa-dispatcher.osa_ssl_cert" /etc/rhn/rhn.conf
>osa-dispatcher.osa_ssl_cert =
>/var/www/html/pub/RHN-ORG-TRUSTED-SSL-CERT
>
>                grep C2S_AS_ROOT /etc/sysconfig/jabberd
># set C2S_AS_ROOT to "yes" to start c2s as root
>C2S_AS_ROOT="no"
>
>
>
>I tried deleting the jabberd database and tables, but to no avail.
>
>                rm -f /var/lib/jabberd/db/*
>
>                spacewalk-sql -i
>                delete from rhnPushDispatcher;
>                delete from rhnPushClient;
>                \quit
>
>
>I also tried re-configuring the jabberd service, to see if that would
>fix it, but it didn’t:
>
>                service osa-dispatcher stop
>service jabberd stop
>
>cp -arv /etc/jabberd /etc/jabberd.bak
>cp -arv /var/lib/jabberd/ /var/lib/jabberd.bak
>rm -rf /etc/jabberd/* /var/lib/jabberd/*
>
>yum reinstall jabberd -y
>spacewalk-setup-jabberd
>
>grep $(hostname) /etc/jabberd/*xml
>
>service jabberd start
>service osa-dispatcher start
>
>
>
>I verified that ports are open:
>
>                nmap -sT -p 5200-5400 localhost
>
>Nmap scan report for localhost (127.0.0.1)
>PORT     STATE SERVICE
>5222/tcp open  xmpp-client
>5269/tcp open  xmpp-server
>5347/tcp open  unknown
>
>
>
>I’ve run out of things to look at at this point. Any ideas?

This looks pretty much like @Andrews error a few days ago. You seem to have 2 osa-duspatcher server with the same name connecting to your jabber instance which are kicking each other.

It is these ids "texv6..." And "r00s..." That indicate the different instances. Maybe you can identify the IP address from where these requests come from.

Robert