Database connection error handling issue

It’'s quite annoying bug (database is PostgreSQL 7.4.7)

  1. Make some users connected and authenticated

  2. Turn off database for few minutes (in my case for backup…)

  3. Try to login another user (it will fail but that is OK, since database is down) - few exceptions will be thrown (one nested if I correctly recall)

  4. Turn database on

  5. Messenger will reconnect to database BUT trying to connect with another client will fail… Those already connected will have jabber running, those not will never connect. Moreover - admin console will be dead…

Not trying to connect during database inactivity will make server behave correctly…

Hi mnemonic,

  1. Messenger will reconnect to database BUT trying to

connect with another client will fail… Those

already connected will have jabber running, those not

will never connect. Moreover - admin console will be

dead…

It sounds to me as if Messenger never reconnects to the database. How are you checking to see that Messenger has reconnected?

Thanks,

Ryan

  1. I’'m turning off database every night for few minutes. So if your assumption (Messenger never reconnects) were true, problem would be every morning… But problem arises sometimes only…

  2. Running ps command in shell shows persistent connections to right database…

So, Messenger reconnects - but has big mess in internal structures and is working incorrectly…

Hi mnemonic,

Ah, you didn’'t originally mention that the problem was intermintent. Are you seeing any messages in the logs on the mornings when Messenger fails to reconnect?

Thanks,

Ryan

Here we go:

  1. ps afx

24478 ? S 0:02 /bin/java -server -Dinstall4j.jvmDir= -Dinstall4j.appDir=/opt/jive_messenger -Dexe4j.moduleName=/opt/jive_messenger/bin/messenge

24479 ? S 0:01 _ /bin/java -server -Dinstall4j.jvmDir= -Dinstall4j.appDir=/opt/jive_messenger -Dexe4j.moduleName=/opt/jive_messenger/bin/mess

24480 ? S 0:22 _ /bin/java -server -Dinstall4j.jvmDir= -Dinstall4j.appDir=/opt/jive_messenger -Dexe4j.moduleName=/opt/jive_messenger/bin/

24766 ? S 0:00 _ /bin/java -server -Dinstall4j.jvmDir= -Dinstall4j.appDir=/opt/jive_messenger -Dexe4j.moduleName=/opt/jive_messenger/bin/

24585 ? S 0:00 _ postgres: jabber jabber 127.0.0.1 idle

24612 ? S 0:00 _ postgres: jabber jabber 127.0.0.1 idle

so connection to database was established, messenger was running (morning state…) but no single person could connect to messenger

  1. messenger logs:

2005.07.22 01:04:27 org.jivesoftware.messenger.auth.DefaultAuthProvider.authenticate(DefaultAuthProv ider.java:98) Exception in DbAuthProvider

org.postgresql.util.PSQLException: An I/O error has occured while flushing the output - Exception: java.net.SocketException: Broken pipe

Stack Trace:

java.net.SocketException: Broken pipe

at java.net.SocketOutputStream.socketWrite0(Native Method)

at java.net.SocketOutputStream.socketWrite(Unknown Source)

at java.net.SocketOutputStream.write(Unknown Source)

at java.io.BufferedOutputStream.flushBuffer(Unknown Source)

at java.io.BufferedOutputStream.flush(Unknown Source)

at org.postgresql.core.PGStream.flush(PGStream.java:411)

at org.postgresql.core.QueryExecutor.sendQueryV3(QueryExecutor.java:338)

at org.postgresql.core.QueryExecutor.executeV3(QueryExecutor.java:121)

at org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:100)

at org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:43)

at org.postgresql.jdbc1.AbstractJdbc1Statement.execute(AbstractJdbc1Statement.java :517)

at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java :50)

at org.postgresql.jdbc1.AbstractJdbc1Statement.executeQuery(AbstractJdbc1Statement .java:233)

at org.jivesoftware.messenger.auth.DefaultAuthProvider.authenticate(DefaultAuthPro vider.java:83)

at org.jivesoftware.messenger.auth.AuthFactory.authenticate(AuthFactory.java:118)

at org.jivesoftware.messenger.handler.IQAuthHandler.login(IQAuthHandler.java:224)

at org.jivesoftware.messenger.handler.IQAuthHandler.handleIQ(IQAuthHandler.java:14 1)

at org.jivesoftware.messenger.handler.IQHandler.process(IQHandler.java:48)

at org.jivesoftware.messenger.IQRouter.handle(IQRouter.java:202)

at org.jivesoftware.messenger.IQRouter.route(IQRouter.java:73)

at org.jivesoftware.messenger.PacketRouter.route(PacketRouter.java:65)

at org.jivesoftware.messenger.net.SocketReadThread.readStream(SocketReadThread.jav a:285)

at org.jivesoftware.messenger.net.SocketReadThread.run(SocketReadThread.java:105)

End of Stack Trace

at org.postgresql.core.PGStream.flush(PGStream.java:415)

at org.postgresql.core.QueryExecutor.sendQueryV3(QueryExecutor.java:338)

at org.postgresql.core.QueryExecutor.executeV3(QueryExecutor.java:121)

at org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:100)

at org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:43)

at org.postgresql.jdbc1.AbstractJdbc1Statement.execute(AbstractJdbc1Statement.java :517)

at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java :50)

at org.postgresql.jdbc1.AbstractJdbc1Statement.executeQuery(AbstractJdbc1Statement .java:233)

at org.jivesoftware.messenger.auth.DefaultAuthProvider.authenticate(DefaultAuthPro vider.java:83)

at org.jivesoftware.messenger.auth.AuthFactory.authenticate(AuthFactory.java:118)

at org.jivesoftware.messenger.handler.IQAuthHandler.login(IQAuthHandler.java:224)

at org.jivesoftware.messenger.handler.IQAuthHandler.handleIQ(IQAuthHandler.java:14 1)

at org.jivesoftware.messenger.handler.IQHandler.process(IQHandler.java:48)

at org.jivesoftware.messenger.IQRouter.handle(IQRouter.java:202)

at org.jivesoftware.messenger.IQRouter.route(IQRouter.java:73)

at org.jivesoftware.messenger.PacketRouter.route(PacketRouter.java:65)

at org.jivesoftware.messenger.net.SocketReadThread.readStream(SocketReadThread.jav a:285)

at org.jivesoftware.messenger.net.SocketReadThread.run(SocketReadThread.java:105)

2005.07.22 01:04:54 org.jivesoftware.messenger.roster.RosterItemProvider.getItems(RosterItemProvider .java:313) Internal server error

org.postgresql.util.PSQLException: An I/O error has occured while flushing the output - Exception: java.net.SocketException: Broken pipe

Stack Trace:

java.net.SocketException: Broken pipe

at java.net.SocketOutputStream.socketWrite0(Native Method)

at java.net.SocketOutputStream.socketWrite(Unknown Source)

at java.net.SocketOutputStream.write(Unknown Source)

at java.io.BufferedOutputStream.flushBuffer(Unknown Source)

at java.io.BufferedOutputStream.flush(Unknown Source)

at org.postgresql.core.PGStream.flush(PGStream.java:411)

at org.postgresql.core.QueryExecutor.sendQueryV3(QueryExecutor.java:338)

at org.postgresql.core.QueryExecutor.executeV3(QueryExecutor.java:121)

at org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:100)

at org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:43)

at org.postgresql.jdbc1.AbstractJdbc1Statement.execute(AbstractJdbc1Statement.java :517)

at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java :50)

at org.postgresql.jdbc1.AbstractJdbc1Statement.executeQuery(AbstractJdbc1Statement .java:233)

at org.jivesoftware.messenger.roster.RosterItemProvider.getItems(RosterItemProvide r.java:281)

at org.jivesoftware.messenger.roster.Roster.(Roster.java:91)

at org.jivesoftware.messenger.roster.RosterManager.getRoster(RosterManager.java:69 )

at org.jivesoftware.messenger.handler.PresenceUpdateHandler.broadcastUpdate(Presen ceUpdateHandler.java:247)

at org.jivesoftware.messenger.handler.PresenceUpdateHandler.process(PresenceUpdate Handler.java:108)

at org.jivesoftware.messenger.handler.PresenceUpdateHandler.process(PresenceUpdate Handler.java:151)

at org.jivesoftware.messenger.SessionManager$ClientSessionListener.onConnectionClo se(SessionManager.java:1037)

at org.jivesoftware.messenger.net.SocketConnection.notifyCloseListeners(SocketConn ection.java:295)

at org.jivesoftware.messenger.net.SocketConnection.close(SocketConnection.java:236 )

at org.jivesoftware.messenger.handler.IQAuthHandler.login(IQAuthHandler.java:204)

at org.jivesoftware.messenger.handler.IQAuthHandler.handleIQ(IQAuthHandler.java:14 1)

at org.jivesoftware.messenger.handler.IQHandler.process(IQHandler.java:48)

at org.jivesoftware.messenger.IQRouter.handle(IQRouter.java:202)

at org.jivesoftware.messenger.IQRouter.route(IQRouter.java:73)

at org.jivesoftware.messenger.PacketRouter.route(PacketRouter.java:65)

at org.jivesoftware.messenger.net.SocketReadThread.readStream(SocketReadThread.jav a:285)

at org.jivesoftware.messenger.net.SocketReadThread.run(SocketReadThread.java:105)

2005.07.22 01:04:54 org.jivesoftware.messenger.auth.DefaultAuthProvider.authenticate(DefaultAuthProv ider.java:98) Exception in DbAuthProvider

org.postgresql.util.PSQLException: An I/O error has occured while flushing the output - Exception: java.net.SocketException: Broken pipe

Stack Trace:

java.net.SocketException: Broken pipe

at java.net.SocketOutputStream.socketWrite0(Native Method)

at java.net.SocketOutputStream.socketWrite(Unknown Source)

at java.net.SocketOutputStream.write(Unknown Source)

at java.io.BufferedOutputStream.flushBuffer(Unknown Source)

at java.io.BufferedOutputStream.flush(Unknown Source)

at org.postgresql.core.PGStream.flush(PGStream.java:411)

at org.postgresql.core.QueryExecutor.sendQueryV3(QueryExecutor.java:338)

at org.postgresql.core.QueryExecutor.executeV3(QueryExecutor.java:121)

at org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:100)

at org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:43)

at org.postgresql.jdbc1.AbstractJdbc1Statement.execute(AbstractJdbc1Statement.java :517)

at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java :50)

at org.postgresql.jdbc1.AbstractJdbc1Statement.executeQuery(AbstractJdbc1Statement .java:233)

at org.jivesoftware.messenger.auth.DefaultAuthProvider.authenticate(DefaultAuthPro vider.java:83)

at org.jivesoftware.messenger.auth.AuthFactory.authenticate(AuthFactory.java:118)

at org.jivesoftware.messenger.handler.IQAuthHandler.login(IQAuthHandler.java:224)

at org.jivesoftware.messenger.handler.IQAuthHandler.handleIQ(IQAuthHandler.java:14 1)

at org.jivesoftware.messenger.handler.IQHandler.process(IQHandler.java:48)

at org.jivesoftware.messenger.IQRouter.handle(IQRouter.java:202)

at org.jivesoftware.messenger.IQRouter.route(IQRouter.java:73)

at org.jivesoftware.messenger.PacketRouter.route(PacketRouter.java:65)

at org.jivesoftware.messenger.net.SocketReadThread.readStream(SocketReadThread.jav a:285)

at org.jivesoftware.messenger.net.SocketReadThread.run(SocketReadThread.java:105)

End of Stack Trace

at org.postgresql.core.PGStream.flush(PGStream.java:415)

at org.postgresql.core.QueryExecutor.sendQueryV3(QueryExecutor.java:338)

at org.postgresql.core.QueryExecutor.executeV3(QueryExecutor.java:121)

at org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:100)

at org.postgresql.core.QueryExecutor.execute(QueryExecutor.java:43)

at org.postgresql.jdbc1.AbstractJdbc1Statement.execute(AbstractJdbc1Statement.java :517)

at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java :50)

at org.postgresql.jdbc1.AbstractJdbc1Statement.executeQuery(AbstractJdbc1Statement .java:233)

at org.jivesoftware.messenger.auth.DefaultAuthProvider.authenticate(DefaultAuthPro vider.java:83)

at org.jivesoftware.messenger.auth.AuthFactory.authenticate(AuthFactory.java:118)

at org.jivesoftware.messenger.handler.IQAuthHandler.login(IQAuthHandler.java:224)

at org.jivesoftware.messenger.handler.IQAuthHandler.handleIQ(IQAuthHandler.java:14 1)

at org.jivesoftware.messenger.handler.IQHandler.process(IQHandler.java:48)

at org.jivesoftware.messenger.IQRouter.handle(IQRouter.java:202)

at org.jivesoftware.messenger.IQRouter.route(IQRouter.java:73)

at org.jivesoftware.messenger.PacketRouter.route(PacketRouter.java:65)

at org.jivesoftware.messenger.net.SocketReadThread.readStream(SocketReadThread.jav a:285)

at org.jivesoftware.messenger.net.SocketReadThread.run(SocketReadThread.java:105)

2005.07.22 01:05:15 Failed to reopen connection

org.postgresql.util.PSQLException: An I/O error has occured while flushing the output - Exception: java.net.SocketException: Broken pipe

Stack Trace:

java.net.SocketException: Broken pipe

at java.net.SocketOutputStream.socketWrite0(Native Method)

at java.net.SocketOutputStream.socketWrite(Unknown Source)

at java.net.SocketOutputStream.write(Unknown Source)

at java.io.BufferedOutputStream.flushBuffer(Unknown Source)

at java.io.BufferedOutputStream.flush(Unknown Source)

at org.postgresql.core.PGStream.flush(PGStream.java:411)

at org.postgresql.jdbc1.AbstractJdbc1Connection.closeV3(AbstractJdbc1Connection.ja va:1147)

at org.postgresql.jdbc1.AbstractJdbc1Connection.close(AbstractJdbc1Connection.java :1133)

at org.jivesoftware.database.ConnectionPool.run(ConnectionPool.java:329)

at java.lang.Thread.run(Unknown Source)

End of Stack Trace

at org.postgresql.core.PGStream.flush(PGStream.java:415)

at org.postgresql.jdbc1.AbstractJdbc1Connection.closeV3(AbstractJdbc1Connection.ja va:1147)

at org.postgresql.jdbc1.AbstractJdbc1Connection.close(AbstractJdbc1Connection.java :1133)

at org.jivesoftware.database.ConnectionPool.run(ConnectionPool.java:329)

at java.lang.Thread.run(Unknown Source)

after reading this i’'m realy confused… so connection is established but messenger thinks not??

so connection is established but messenger thinks not??

I’‘m not entirely sure if its a Messenger issue or a driver issue. I’'ve seen similiar stack traces when the connection between Messenger and Oracle has been severed but it has always managed to repair itself.

Which version of Postgre are you using? The Postgre driver Messenger comes with is version 7.4 version 215. Looking at the Postgre driver url=http://jdbc.postgresql.org/download.htmldownload[/url] page it appears there is a slightly newer build (216) available for version 7.4 as well as a driver for version 8 if that is what you are using.

Thanks,

Ryan

Just had a quick look at the code in Jive. Your stack trace shows 2 separate type of events happening

  1. DefaultAuthProvider authenticate is failing because a connection in the connection pool is dead. JDBC drivers will not tell you if a connection is dead, you only find out when you try to use it. You connection is dead because you killed the database.

Note: If you had already logged in with a user, it would be in the cache and therefore the dropped connections would not be noticed as no database request is used. Therefore the problem may appear intermitently.

This first type is JM simply hitting a unexpected runtime condition and recovering appropriately. I think the roster exception is the same type.

  1. The second is from ConnectionPool run method, this is a JM service level thread to test the health of connections. You can see in you trace a log “Failed to reopen connection”, this is when JM notices that a connection is dead, tries to reopen the connection and fails. I would guess that this is JDBC driver dependant, some will allow the connection to be re-established, some won’'t, or maybe some will but not all then time!.

With a postgre db this problem could be fatal to the operation of JM, with an Oracle db it may recover. It poses an interesting question, should JM attempt to do more to handle this problem. Perhaps Matt or Gato can comment?

Hope that helps,

Conor.

Conor,

Very nice analysis of the issues. It may be possible for the connection pooling code to be improved to handle this situation better. I’'ve filed this as JM-343.

Regards,

Matt