I did an OS upgrade, and Jive Messenger isn''t working right anymore!

Openfire Openfire Support
1

Hi,

I did a upgrade from Mandriva 2005LE to 2006.0 this weekend. It went fairly well, and almost everything seems to be working correctly. Except Jive Messenger…

After the upgrade, Messenger ran fine, but wouldn’'t let anybody log in either by Psi or the Admin Console. So, I tried a little bit of troubleshooting.

First I checked to make sure my jive_messenger database was all fine and MySQL was happy – no problems there.

Next, I made sure my Java was fine and the MySQL connector was installed. All good.

Next, I re-installed all the Messenger files except for the jive-messenger.xml file. Still no access.

Next, I ran ethereal to make sure Messenger was talking to MySQL, and it was.

Next, I nuked and recreated my MySQL database. Still no ability to log in with admin:admin. And, yes, the database can be accessed by knoda as user jive, and looks fine.

Finally, I copied over the default jive-messenger.xml file and tried to setup again. Everything is fine up to Administrator Account – it gives the error, “There was an unexpected error encountered when setting the new admin information. Please check your error logs and try to remedy the problem.”. The only error that I can find in the logs is, “Could not find UserManager”. I’'ve also gotten an error:

2005.10.31 02:12:30 org.jivesoftware.util.JiveProperties.insertProperty(JiveProperties.java:214)

java.sql.SQLException: Duplicate entry ‘’’’ for key 1

at com.mysql.jdbc.MysqlIO.checkErrorPacket(MysqlIO.java:2926)

at com.mysql.jdbc.MysqlIO.sendCommand(MysqlIO.java:1571)

at com.mysql.jdbc.ServerPreparedStatement.serverExecute(ServerPreparedStatement.ja va:1120)

at com.mysql.jdbc.ServerPreparedStatement.executeInternal(ServerPreparedStatement. java:675)

at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1162)

at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1079)

at com.mysql.jdbc.PreparedStatement.executeUpdate(PreparedStatement.java:1064)

at org.jivesoftware.util.JiveProperties.insertProperty(JiveProperties.java:211)

at org.jivesoftware.util.JiveProperties.put(JiveProperties.java:191)

at org.jivesoftware.util.JiveGlobals.setProperty(JiveGlobals.java:635)

at org.jivesoftware.messenger.muc.HistoryStrategy.setType(HistoryStrategy.java:115 )

at org.jivesoftware.messenger.muc.HistoryStrategy.setTypeFromString(HistoryStrateg y.java:228)

at org.jivesoftware.messenger.muc.HistoryStrategy.setContext(HistoryStrategy.java: 241)

at org.jivesoftware.messenger.muc.spi.MultiUserChatServerImpl.initialize(MultiUser ChatServerImpl.java:665)

at org.jivesoftware.messenger.XMPPServer.initModules(XMPPServer.java:368)

at org.jivesoftware.messenger.XMPPServer.start(XMPPServer.java:275)

at org.jivesoftware.messenger.XMPPServer.(XMPPServer.java:133)

at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)

at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessor Impl.java:39)

at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructor AccessorImpl.java:27)

at java.lang.reflect.Constructor.newInstance(Constructor.java:494)

at java.lang.Class.newInstance0(Class.java:350)

at java.lang.Class.newInstance(Class.java:303)

at org.jivesoftware.messenger.starter.ServerStarter.start(ServerStarter.java:82)

at org.jivesoftware.messenger.starter.ServerStarter.main(ServerStarter.java:46)

at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)

at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)

at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.ja va:25)

at java.lang.reflect.Method.invoke(Method.java:585)

at com.exe4j.runtime.LauncherEngine.launch(Unknown Source)

at com.install4j.runtime.Launcher.main(Unknown Source)

while trying to log in the Admin Console.

I’‘ve been banging my head on this problem for a while, and it’‘s quite late here (so if stuff doesn’‘t make sense, that’'s why). So, any pointers on how to troubleshoot further would be very much appreciated!

Cliff

2

Are you using a firewall? Maybe some permissions are wrong now?

3

Yes, I’‘m using a firewall. Turning it on or off makes no difference. Besides, I’'m testing connections from localhost to localhost, and that is not restricted by my firewall. (Psi MySQL and Messenger are all on the same physical machine.)

Maybe some permissions are wrong somewhere, but all my RPMs verify to be fine, and /usr/local/jive_messenger should not have been touched by my OS’‘s upgrade – and the permissions would have been reset on the re-install anyway. Also, Azerus works fine too, so most likely Java isn’'t dead either (I am using the exact same java as before, although it needed to be re-installed after being downgraded during the upgrade).

Any other ideas? Is there a verbose way to run Messenger?

4

Hello.

Try to log in the MySQL with the user to see if it still have the permissions in the DB

  1. root@sepsrv123:~# mysql -u’‘root’’ -p’‘password’’ -h’‘localhost’’ -D’‘jive’’ -e’‘select count(*) from jiveUser’’

*----

count(*)

*----

4104

*----

root@sepsrv123:~#

Check the connection in jive-messenger.xml at $JM/conf

Check Java too.

root@sepsrv123:/usr/local/jive_messenger# java -version

java version “1.5.0_04”

Java™ 2 Runtime Environment, Standard Edition (build 1.5.0_04-b05)

Java HotSpot™ Client VM (build 1.5.0_04-b05, mixed mode, sharing)

root@sepsrv123:/usr/local/jive_messenger#

Try to telnet to the Jabber port (5222 default):

root@sepsrv123:/usr/local/jive_messenger# telnet localhost 5222

Trying 127.0.0.1…

Connected to localhost.

Escape character is ‘’^]’’.

quit

Terminated

root@sepsrv123:/usr/local/jive_messenger#

Check the MySQL log (depends on the distro), it might have something from the JM.

Everything looks fine?

regards,

Rodrigo.

5

I restored my MySQL database and jive-messenger.xml to copies that did work to do these tests.

Try to log in the MySQL (using same settings that Jive Messenger uses)

*----

count(*)

*----

4

*----

< Correct.

Check the connection in jive-messenger.xml

< Looks good to me

Check Java too

java version “1.5.0_05”

Java™ 2 Runtime Environment, Standard Edition (build 1.5.0_05-b05)

Java HotSpot™ Server VM (build 1.5.0_05-b05, mixed mode)

< Correct.

Try to telnet to the Jabber port

Trying 127.0.0.1…

Connected to pinky.fuzzy (127.0.0.1).

Escape character is ‘’^]‘’.

Check the MySQL log

051031 13:59:39 mysqld started

051031 13:59:39 InnoDB: Started; log sequence number 0 43674

/usr/sbin/mysqld: ready for connections.

Version: ‘‘4.1.12’’ socket: ‘’/var/lib/mysql/mysql.sock’’ port: 3306 Source distribution

< Looks all good.

Any more ideas?

6

I just did a thorough ReiserFS check on all my partitions since under some conditions the filesystem can get messed up and have problems reading some files. Nothing showed up.

So, I’'m still looking for any ideas. Is there a way to have Messenger be much more verbose?

7

Can you try to setup completely fresh JM install?

8

I tried a completely fresh JM install as suggested. Instead of trying 2.3.0b1 again (it was great while it worked…), I used 2.2.2 for this install. I started with a new database too, and prepared that as it should be. I’'m still using MySQL though.

The result: is exactly the same as before. JM successfull connects to the MySQL database, but I cannot change the admin password during the web setup. It tells me to check the logs, and still the only thing I can find of interest is, “Could not find UserManager”.

9

Cliff,

One thing you could try is turning on debug logging. To do so, add the following to the XML config file:

[/pre]

Of course, if you already have a log section in the file, you should modify it rather than adding a new log section.

Regards,

Matt

10

Where do I put the ?

11

Hopefully I guessed the section for

Does this give any clues?

12

Cliff,

log under jive is correct. Are you looking in the debug log file (in the logs dire) for info?

Regards,

Matt

13

Yes, that connection log came from debug.log.

Since then, as I’‘ve left JM running, I’'ve gotten more info in the debug.log file from other servers asking for presence information I assume. I suppose I might as well post the new info in case it helps to track down what may not be working:

2005.11.04 11:51:22 Connect Socket[addr=/208.245.212.98,port=43990,localport=5269]

2005.11.04 11:51:23 RS - Received dialback key from host: jabber.org to: pinky.dnsalias.net

2005.11.04 11:51:23 RS - Trying to connect to Authoritative Server: jabber.org:5269

2005.11.04 11:51:23 RS - Connection to AS: jabber.org:5269 successfull

2005.11.04 11:51:24 RS - Asking AS to verify dialback key for ided64e443

2005.11.04 11:51:24 RS - Key was VERIFIED by the Authoritative Server for: jabber.org

2005.11.04 11:51:24 RS - Closing connection to Authoritative Server: jabber.org

2005.11.04 11:51:24 RS - Sending key verification result to OS: jabber.org

2005.11.04 11:51:25 OS - Trying to connect to jabber.org:5269

2005.11.04 11:51:25 OS - Connection to jabber.org:5269 successfull

2005.11.04 11:51:25 OS - Sent dialback key to host: jabber.org id: 3581776B3D2E5 from domain: pinky.dnsalias.net

2005.11.04 11:51:25 Connect Socket[addr=/208.245.212.98,port=44007,localport=5269]

2005.11.04 11:51:25 AS - Verifying key for host: jabber.org id: 3581776B3D2E5

2005.11.04 11:51:25 AS - Key was: VALID for host: jabber.org id: 3581776B3D2E5

2005.11.04 11:51:25 AS - Connection closed for host: jabber.org id: 3581776B3D2E5

2005.11.04 11:51:25 OS - Validation GRANTED from: jabber.org id: 3581776B3D2E5 for domain: pinky.dnsalias.net

2005.11.04 12:00:06 Logging off jabber.org on org.jivesoftware.messenger.net.SocketConnection@c38157 socket: Socket[addr=/208.245.212.98,port=43990,localport=5269] session: org.jivesoftware.messenger.server.IncomingServerSession@1609c13 status: 1 address: jabber.org id: ed64e443

2005.11.04 12:23:17 Finishing Outgoing Server Reader. Closing session: org.jivesoftware.messenger.server.OutgoingServerSession@172c47b status: -1 address: jabber.org id: 3581776B3D2E5

java.net.SocketException: Socket closed

at java.net.SocketInputStream.socketRead0(Native Method)

at java.net.SocketInputStream.read(SocketInputStream.java:129)

at sun.nio.cs.StreamDecoder$CharsetSD.readBytes(StreamDecoder.java:411)

at sun.nio.cs.StreamDecoder$CharsetSD.implRead(StreamDecoder.java:453)

at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:183)

at java.io.InputStreamReader.read(InputStreamReader.java:167)

at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:2971)

at org.xmlpull.mxp1.MXParser.more(MXParser.java:3025)

at org.xmlpull.mxp1.MXParser.nextImpl(MXParser.java:1144)

at org.xmlpull.mxp1.MXParser.nextToken(MXParser.java:1100)

at org.dom4j.io.XPPPacketReader.parseDocument(XPPPacketReader.java:268)

at org.jivesoftware.messenger.server.OutgoingServerSocketReader$1.run(OutgoingServ erSocketReader.java:91)

2005.11.04 12:23:34 Connect Socket[addr=/144.173.6.104,port=59418,localport=5269]

2005.11.04 12:23:34 RS - Received dialback key from host: jabber.ex.ac.uk to: pinky.dnsalias.net

2005.11.04 12:23:35 RS - Trying to connect to Authoritative Server: jabber.ex.ac.uk:5269

2005.11.04 12:23:35 RS - Connection to AS: jabber.ex.ac.uk:5269 successfull

2005.11.04 12:23:35 RS - Asking AS to verify dialback key for idcc1d64b9

2005.11.04 12:23:35 RS - Key was VERIFIED by the Authoritative Server for: jabber.ex.ac.uk

2005.11.04 12:23:35 RS - Closing connection to Authoritative Server: jabber.ex.ac.uk

2005.11.04 12:23:35 RS - Sending key verification result to OS: jabber.ex.ac.uk

2005.11.04 12:23:35 OS - Trying to connect to jabber.ex.ac.uk:5269

2005.11.04 12:23:36 OS - Connection to jabber.ex.ac.uk:5269 successfull

2005.11.04 12:23:36 OS - Sent dialback key to host: jabber.ex.ac.uk id: 3991499653 from domain: pinky.dnsalias.net

2005.11.04 12:23:36 Connect Socket[addr=/144.173.6.104,port=59483,localport=5269]

2005.11.04 12:23:36 AS - Verifying key for host: jabber.ex.ac.uk id: 3991499653

2005.11.04 12:23:36 AS - Key was: VALID for host: jabber.ex.ac.uk id: 3991499653

2005.11.04 12:23:36 AS - Connection closed for host: jabber.ex.ac.uk id: 3991499653

2005.11.04 12:23:36 OS - Validation GRANTED from: jabber.ex.ac.uk id: 3991499653 for domain: pinky.dnsalias.net

2005.11.04 12:33:34 Logging off jabber.ex.ac.uk on org.jivesoftware.messenger.net.SocketConnection@14af9f7 socket: Socket[addr=/144.173.6.104,port=59418,localport=5269] session: org.jivesoftware.messenger.server.IncomingServerSession@160e069 status: 1 address: jabber.ex.ac.uk id: cc1d64b9

2005.11.04 12:33:36 Finishing Outgoing Server Reader. Closing session: org.jivesoftware.messenger.server.OutgoingServerSession@12d26d2 status: 1 address: jabber.ex.ac.uk id: 3991499653

java.io.EOFException: no more data available - expected end tag </stream:stream> to close start tag stream:stream from line 1, parser stopped on END_TAG seen …sult from=’‘jabber.ex.ac.uk’’ to=’‘pinky.dnsalias.net’’ type=’‘valid’’/>… @1:228

at org.xmlpull.mxp1.MXParser.fillBuf(MXParser.java:3014)

at org.xmlpull.mxp1.MXParser.more(MXParser.java:3025)

at org.xmlpull.mxp1.MXParser.nextImpl(MXParser.java:1144)

at org.xmlpull.mxp1.MXParser.nextToken(MXParser.java:1100)

at org.dom4j.io.XPPPacketReader.parseDocument(XPPPacketReader.java:268)

at org.jivesoftware.messenger.server.OutgoingServerSocketReader$1.run(OutgoingServ erSocketReader.java:91)

14

Since I’'m running out of ideas, I tried reinstalling Java. Still nothing.

Has anybody deduced anything from my posted debug logs?

15

First I have to give a big thank-you to Matt for all the help in working around this problem.

It seems as though at some point JM is having problems using my MySQL, even though other applications can use it perfectly fine. My hunch is that either the MySQL connector or JM has some incompatibility. It could also be that Mandriva broke their MySQL package, but as I said, I have no other problems accessing MySQL, so I don’‘t think that this is the case. Of course, it could just be that my computer is broken and I don’'t know it.

Anyhow, although MySQL would work a bit better for me, the embedded database would also work fine too. So, the temporary fix of the problem was to migrate from MySQL to the embedded database. My database was small enough to do by hand, so I cannot suggest any scripts or programs to do the work.

For reference, I have the following RPMs installed on Mandriva Linux 2006:

jdk-1.5.0_05-fcs

libmysql14-4.1.12-3mdk

MySQL-4.1.12-3mdk

This problem occurred on both JM 2.2.2 and JM 2.3.0b1 with mysql-connector 3.1.11.

16

Hello Cliff

For reference, I have the following RPMs installed on

Mandriva Linux 2006:

jdk-1.5.0_05-fcs

libmysql14-4.1.12-3mdk

MySQL-4.1.12-3mdk

This problem occurred on both JM 2.2.2 and JM 2.3.0b1

with mysql-connector 3.1.11.

I don’‘t know about Mandriva, but some distros have the MySQL packages and MySQL-dev or MySQL-devel (the development packages), maybe it’‘s missing and JM uses it. It’'s just a thought…

And what about the localhost in /etc/hosts? Some distros too have localhost.localdomain (like Debian and Debian-like) and I have problems to JM that not logged in MySQL because localhost.localdomain is first then localhost. Just another thought too…

regards,

Rodrigo.

Message was edited by:

mrodrigom

17

I don’'t know about Mandriva, but some distros have

the MySQL packages and MySQL-dev or MySQL-devel (the

development packages), maybe it’'s missing and JM

uses it. It’'s just a thought…

Yes, I do have libmysql14-devel-4.1.12-3mdk installed too. Possibly it could be that I need a more advanced MySQL like the MySQL-Max-4.1.12-3mdk package? Either way, JM is not mentioning that anything is wrong, even in debug mode.

And what about the localhost in /etc/hosts? Some

distros too have localhost.localdomain (like Debian

and Debian-like) and I have problems to JM that not

logged in MySQL because localhost.localdomain is

first then localhost. Just another thought too…

Nope, no localhost.localdomain there. Besides, it’‘s exactly the same as before I upgraded. I’‘m using the same name resolving method too. Also, my local nameserver seems to be fine (no changes to that either). There was a small inconsistency between /etc/hosts and my nameserver though. I fixed it, and everything is still the same. Just to make sure we’‘re on the same page, I have ‘‘127.0.0.1 localhost’’ plus a couple other entries (with different IPs) in my /etc/hosts file. My nameserver resolves 127.0.0.1<–>localhost. My MySQL connection is done through localhost. I can verify that there is an active connection made between JM and MySQL too – I suppose it’'s just broken.

I decided to take a closer look at the connection between JM and MySQL again through ethereal. If I got it right, here’'s part of the conversation when I try to login via Psi (my username is cdugal):

(~out~)…/…SELECT password FROM jiveUser WHERE username=?

(~in~)…def…?..?..D…def.jive_messenger.jiveUser. jiveUser.password.password.!.`…

(~out~)…cdugal

(~in~)…D…def.jive_messenger.jiveUser.jiveUser.password.password.!.`… …

Where (~out) and (in~) denote stream direction.

Interestingly, if I run mysql and type ‘‘SELECT password FROM jiveUser WHERE username=cdugal’’, I get my password just fine.

18

Maybe it’'s a stupid question, but have you looked in the MySQL logs?

Can you put here the part where JM is started?

regards,

Rodrigo.

19

Ok, I’'ll take that direction.

I figured out how to enable the “General Query Log” of MySQL.

For those that are curious, it involves adding a line something like this to /etc/sysconfig/mysqld:

MYSQLD_OPTIONS="–log=/var/log/mysqld/mysqldquery.log"

Anyhow, I’'ve logged starting MySQL, starting JM, attempting to log on as cdugal in Psi, stopping JM, and stopping MySQL. (I believe the “UNKNOWN_MYSQL_US@localhost” part is from the MySQL startup script that confirms MySQL is loaded by seeing if trying to access MySQL with an invalid username returns with a valid access denied message.)

======

/usr/sbin/mysqld, Version: 4.1.12-log. started with:

Tcp port: 3306 Unix socket: /var/lib/mysql/mysql.sock

Time Id Command Argument

051109 11:43:56 1 Connect UNKNOWN_MYSQL_US@localhost as anonymous on

1 Quit

051109 11:44:14 2 Connect jive@localhost on jive_messenger

2 Query SET NAMES utf8

2 Query SET character_set_results = NULL

2 Query SHOW VARIABLES

2 Query SHOW COLLATION

2 Query SET autocommit=1

2 Query SET autocommit=1

2 Query SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED

3 Connect jive@localhost on jive_messenger

3 Query SET NAMES utf8

3 Query SET character_set_results = NULL

3 Query SHOW VARIABLES

3 Query SHOW COLLATION

3 Query SET autocommit=1

3 Query SET autocommit=1

3 Query SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED

4 Connect jive@localhost on jive_messenger

4 Query SET NAMES utf8

4 Query SET character_set_results = NULL

4 Query SHOW VARIABLES

4 Query SHOW COLLATION

4 Query SET autocommit=1

4 Query SET autocommit=1

4 Query SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED

5 Connect jive@localhost on jive_messenger

5 Query SET NAMES utf8

5 Query SET character_set_results = NULL

5 Query SHOW VARIABLES

5 Query SHOW COLLATION

5 Query SET autocommit=1

5 Query SET autocommit=1

5 Query SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED

6 Connect jive@localhost on jive_messenger

6 Query SET NAMES utf8

6 Query SET character_set_results = NULL

6 Query SHOW VARIABLES

6 Query SHOW COLLATION

6 Query SET autocommit=1

6 Query SET autocommit=1

6 Query SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED

2 Prepare SELECT majorVersion, minorVersion FROM jiveVersion

2 Execute SELECT majorVersion, minorVersion FROM jiveVersion

2 Prepare SELECT name, propValue FROM jiveProperty

2 Execute SELECT name, propValue FROM jiveProperty

2 Prepare SELECT count(*) FROM jiveID

2 Execute SELECT count(*) FROM jiveID

051109 11:44:18 2 Prepare SELECT roomID, creationDate, modificationDate, name, naturalName, description, lockedDate, emptyDate, canChangeSubject, maxUsers, publicRoom, moderated, membersOnly, canInvite, password, canDiscoverJID, logEnabled, subject, rolesToBroadcast, useReservedNick, canChangeNick, canRegister FROM mucRoom WHERE emptyDate IS NULL or emptyDate > ?

2 Execute SELECT roomID, creationDate, modificationDate, name, naturalName, description, lockedDate, emptyDate, canChangeSubject, maxUsers, publicRoom, moderated, membersOnly, canInvite, password, canDiscoverJID, logEnabled, subject, rolesToBroadcast, useReservedNick, canChangeNick, canRegister FROM mucRoom WHERE emptyDate IS NULL or emptyDate > ?

2 Prepare SELECT roomID, sender, nickname, time, subject, body FROM mucConversationLog WHERE time>? AND (nickname <> ‘’’’ OR subject IS NOT NULL) ORDER BY time

2 Execute SELECT roomID, sender, nickname, time, subject, body FROM mucConversationLog WHERE time>? AND (nickname <> ‘’’’ OR subject IS NOT NULL) ORDER BY time

2 Prepare SELECT roomID,jid,affiliation FROM mucAffiliation

2 Execute SELECT roomID,jid,affiliation FROM mucAffiliation

2 Prepare SELECT roomID,jid, nickname FROM mucMember

2 Execute SELECT roomID,jid, nickname FROM mucMember

051109 11:44:53 2 Prepare SELECT password FROM jiveUser WHERE username=?

2 Execute SELECT password FROM jiveUser WHERE username=?

051109 11:44:59 2 Quit

3 Quit

4 Quit

5 Quit

6 Quit

======

Again I see ‘‘SELECT password FROM jiveUser WHERE username=?’’, where I would expect to see “SELECT password FROM jiveUser WHERE username=’‘cdugal’’”.

As I mentioned, the MySQL error log does not show anything useful. But, for those that are interested:

======

051109 11:43:55 mysqld started

051109 11:43:55 InnoDB: Started; log sequence number 0 43684

/usr/sbin/mysqld: ready for connections.

Version: ‘‘4.1.12-log’’ socket: ‘’/var/lib/mysql/mysql.sock’’ port: 3306 Source distribution

051109 11:45:10 /usr/sbin/mysqld: Normal shutdown

051109 11:45:10 InnoDB: Starting shutdown…

051109 11:45:12 InnoDB: Shutdown completed; log sequence number 0 43684

051109 11:45:12 /usr/sbin/mysqld: Shutdown complete

051109 11:45:12 mysqld ended

======

20

I upgraded to JM 2.3.0b2 to see if there was any change in the situation, but unfortunately there is none. I still can’'t use a MySQL database, but the embedded one works fine.