Hi all,
Last night i got a backend disabled notification via jmx on one of our test
servers. When i checked the logs i discovered that there was an error ("Failed
to get a connection on backend 'vieo_ccs_1' but an idle connection was
expected") when sequoia went to get a connection out of the pool. It appears
that the pool had somehow drained to 0 connections even thoe i have a
minpoolsize of 5. On closer inspection there was also a nullpointer exception
in the RemoveIdleConnectionsThread. Is it possible that there was some kind of
race condition related to aquiring and releasing connections? Is it dangerous
to use a pool with no idleTimeout? As a work around should I try one of the
other connection managers? I suppose this all may be just a sympton of a
problem with postgresql or the jdbc driver but the other backend which is on
the same postgres server was ok in processing the request?
I'm using sequoia 2.10.9 in a raidb1 configuration with 2 postgresql backends
per controller. (normally 2 controller but in this scenario there was only 1).
My backend connection manager configuration is :
<ConnectionManager vLogin="postgres" rLogin="postgres" rPassword="*******">
<VariablePoolConnectionManager initPoolSize="10" minPoolSize="5"
maxPoolSize="50" idleTimeout="30" waitTimeout="10"/>
</ConnectionManager>
Here are the relevaent log records (output from sequoia is piped through jboss
standard out logger):2007-10-10 06:59:58,727 402261433 INFO [STDOUT] (Thread-16:) 06:59:58,727 ERROR sequoia.controller.connection Failed to get a connection on backend 'vieo_ccs_1' but an idle connection was expected 2007-10-10 06:59:58,738 402261444 DEBUG [com.vieo.ccs.model.process.impl.WorkflowProcessStatusBean] (EJB-Timer-4[target=jboss.j2ee:service=EJB3,ear=vieo-ccs.ear,jar=vieo-ccs.jar,name=WorkflowProcessStatusBean]:) timeoutHandler() checking for mismatched processes... 2007-10-10 06:59:58,771 402261477 INFO [STDOUT] (Thread-16:) 06:59:58,769 ERROR sequoia.controller.connection Failed to get a connection on backend 'vieo_ccs_1' but an idle connection was expected 06:59:58,770 ERROR sequoia.controller.connection Failed to get a connection on backend 'vieo_ccs_1' but an idle connection was expected 06:59:58,770 ERROR sequoia.controller.connection Failed to get a connection on backend 'vieo_ccs_1' but an idle connection was expected 2007-10-10 06:59:58,771 402261477 ERROR [STDERR] (Thread-17:) Exception in thread "RemoveIdleConnectionsThread for backend:vieo_ccs_1" java.lang.NullPointerException 2007-10-10 06:59:58,803 402261509 ERROR [STDERR] (Thread-17:) at org.continuent.sequoia.controller.connection.VariablePoolConnectionManager$RemoveIdleConnectionsThread.run(VariablePoolConnectionManager.java:628) 2007-10-10 06:59:58,854 402261560 DEBUG [com.vieo.ccs.web.mdb.ProcessMonitorBean] (WorkManager(4)-40252:) ProcessMonitorBean received ProcessStatusMessage: null 2007-10-10 06:59:58,854 402261560 DEBUG [com.vieo.ccs.web.mdb.ProcessMonitorBean] (WorkManager(4)-40252:) Ignoring ProcessStateMessage with empty StatusText 2007-10-10 06:59:58,856 402261562 DEBUG [com.vieo.ccs.server.annunciator.AnnunciatorBroadcastBean] (WorkManager(4)-40253:) AnnunciatorBroadcastBean received ProcessStatusMessage: 2676397 : System Test : START 2007-10-10 06:59:58,856 402261562 DEBUG [com.vieo.ccs.server.annunciator.AnnunciatorBroadcastBean] (WorkManager(4)-40253:) Ignoring process state with empty status text 2007-10-10 06:59:58,974 402261680 INFO [STDOUT] (Thread-16:) 06:59:58,973 WARN DatabaseBackend.vieo_ccs.vieo_ccs_1 A worker thread was still processing task StatementExecuteUpdateTask from transaction 61837 (INSERT INTO JMS_MESSAGES (MESSAGEID, DESTINATION, MESSAGEBLOB, TXID, TXOP) VALUES(?,?,?,?,?)/<!%L|13397|!%><!%S|TOPIC.ProcessStateTopic.ID:15.-2147483648|!%><!%B|rO0ABXoAAAKQBAMAEVByb2Nlc3NTdGF0ZVRvcGljAAAAAAEAAAAAAAAAAAAAAAQHABhJRDoxNy0x MTkxOTcwNzk4NzI0MTMzOTgAAAEVhv78hAEJ/////wAJAAABBwAFSUQ6MTcAAAAACAAAAAECKTw/ eG1sIHZlcnNpb249IjEuMCIgZW5jb2Rpbmc9IlVURi04IiBz 2007-10-10 06:59:58,974 402261680 INFO [STDOUT] (Thread-16:) dGFuZGFsb25lPSJ5ZXMiPz48RW52 ZWxvcGUgdmVyc2lvbj0iMS4yIiB4c2k6bm9OYW1lc3BhY2VTY2hlbWFMb2NhdGlvbj0iVmllb01l c3NhZ2UtMS4yLnhzZCIgeG1sbnM6eHNpPSJodHRwOi8vd3d3LnczLm9yZy8yMDAxL1hNTFNjaGVt YS1pbnN0YW5jZSI+PE1lc3NhZ2VDb250ZW50IHhzaTp0eXBlPSJQcm9jZXNzU3RhdGVNZXNzYWdl Ij48VHlwZT5TdGFydDwvVHlwZT48VGltZT4yMDA3LTEwLTEwVDA2OjU5OjU4LjcyMiswODowMDwv VGltZT48U3RhdGU+PFByb2Nlc3NJRD4yNjc2Mzk3PC9Qcm9jZXNzSUQ+PFByb2Nlc3NEZWZpbml0 aW9uTmFtZT5TeXN0ZW0gVGVzdDwvUHJvY2Vzc0RlZmluaXRpb25OYW1lPjxQcm9jZXNzU3RhcnRU aW1lPjIwMDctMTAtMTBUM 2007-10-10 06:59:58,974 402261680 INFO [STDOUT] (Thread-16:) DY6NTk6NTguNjk4KzA4OjAwPC9Qcm9jZXNzU3RhcnRUaW1lPjxOb2Rl SUQ+MjI3NjQ4NjwvTm9kZUlEPjxEaXNwbGF5UHJpb3JpdHk+LTEwMDA8L0Rpc3BsYXlQcmlvcml0 eT48L1N0YXRlPjwvTWVzc2FnZUNvbnRlbnQ+PC9FbnZlbG9wZT4= |!%><!%N|-5|!%><!%S|T|!%>), aborting the request execution. 06:59:58,974 INFO sequoia.controller.connection 0 connections freed on "jdbc:postgresql://localhost/vieo_ccs_1" 06:59:58,974 WARN sequoia.controller.connection Some connections are still active, destroying them. 2007-10-10 06:59:59,055 402261761 INFO [STDOUT] (Thread-16:) 06:59:59,054 WARN controller.loadbalancer.RAIDb1 Active transactions after backend vieo_ccs_1 is disabled: [61836] 2007-10-10 06:59:59,055 402261761 INFO [STDOUT] (Thread-16:) 06:59:59,055 ERROR backend.DatabaseBackend.vieo_ccs_1 Disabling backend vieo_ccs_1 because it is no more reachable. 2007-10-10 06:59:59,056 402261762 INFO [STDOUT] (Thread-16:) 06:59:59,055 WARN backend.DatabaseBackend.vieo_ccs_1 Task execution failed (java.sql.SQLException: Backend vieo_ccs_1 is no more reachable.) 2007-10-10 06:59:59,115 402261821 INFO [STDOUT] (Thread-16:) 06:59:59,112 WARN DatabaseBackend.vieo_ccs.vieo_ccs_1 Unable to remove task StatementExecuteUpdateTask from transaction 61837 (INSERT INTO JMS_MESSAGES (MESSAGEID, DESTINATION, MESSAGEBLOB, TXID, TXOP) VALUES(?,?,?,?,?)/<!%L|13397|!%><!%S|TOPIC.ProcessStateTopic.ID:15.-2147483648|!%><!%B|rO0ABXoAAAKQBAMAEVByb2Nlc3NTdGF0ZVRvcGljAAAAAAEAAAAAAAAAAAAAAAQHABhJRDoxNy0x MTkxOTcwNzk4NzI0MTMzOTgAAAEVhv78hAEJ/////wAJAAABBwAFSUQ6MTcAAAAACAAAAAECKTw/ eG1sIHZlcnNpb249IjEuMCIgZW5jb2Rpbmc9IlVURi04IiBzdGFuZGFsb25lPSJ5ZXMi 2007-10-10 06:59:59,115 402261821 INFO [STDOUT] (Thread-16:) Pz48RW52 ZWxvcGUgdmVyc2lvbj0iMS4yIiB4c2k6bm9OYW1lc3BhY2VTY2hlbWFMb2NhdGlvbj0iVmllb01l c3NhZ2UtMS4yLnhzZCIgeG1sbnM6eHNpPSJodHRwOi8vd3d3LnczLm9yZy8yMDAxL1hNTFNjaGVt YS1pbnN0YW5jZSI+PE1lc3NhZ2VDb250ZW50IHhzaTp0eXBlPSJQcm9jZXNzU3RhdGVNZXNzYWdl Ij48VHlwZT5TdGFydDwvVHlwZT48VGltZT4yMDA3LTEwLTEwVDA2OjU5OjU4LjcyMiswODowMDwv VGltZT48U3RhdGU+PFByb2Nlc3NJRD4yNjc2Mzk3PC9Qcm9jZXNzSUQ+PFByb2Nlc3NEZWZpbml0 aW9uTmFtZT5TeXN0ZW0gVGVzdDwvUHJvY2Vzc0RlZmluaXRpb25OYW1lPjxQcm9jZXNzU3RhcnRU aW1lPjIwMDctMTAtMTBUMDY6NTk6NTguNjk4KzA4O 2007-10-10 06:59:59,115 402261821 INFO [STDOUT] (Thread-16:) jAwPC9Qcm9jZXNzU3RhcnRUaW1lPjxOb2Rl SUQ+MjI3NjQ4NjwvTm9kZUlEPjxEaXNwbGF5UHJpb3JpdHk+LTEwMDA8L0Rpc3BsYXlQcmlvcml0 eT48L1N0YXRlPjwvTWVzc2FnZUNvbnRlbnQ+PC9FbnZlbG9wZT4= |!%><!%N|-5|!%><!%S|T|!%>) from pending request queue 06:59:59,112 ERROR DatabaseBackend.vieo_ccs.vieo_ccs_1 Failed to remove task StatementExecuteUpdateTask from transaction 61837 (INSERT INTO JMS_MESSAGES (MESSAGEID, DESTINATION, MESSAGEBLOB, TXID, TXOP) VALUES(?,?,?,?,?)/<!%L|13397|!%><!%S|TOPIC.ProcessStateTopic.ID:15.-2147483648|!%><!%B|rO 2007-10-10 06:59:59,115 402261821 INFO [STDOUT] (Thread-16:) 0ABXoAAAKQBAMAEVByb2Nlc3NTdGF0ZVRvcGljAAAAAAEAAAAAAAAAAAAAAAQHABhJRDoxNy0x MTkxOTcwNzk4NzI0MTMzOTgAAAEVhv78hAEJ/////wAJAAABBwAFSUQ6MTcAAAAACAAAAAECKTw/ eG1sIHZlcnNpb249IjEuMCIgZW5jb2Rpbmc9IlVURi04IiBzdGFuZGFsb25lPSJ5ZXMiPz48RW52 ZWxvcGUgdmVyc2lvbj0iMS4yIiB4c2k6bm9OYW1lc3BhY2VTY2hlbWFMb2NhdGlvbj0iVmllb01l c3NhZ2UtMS4yLnhzZCIgeG1sbnM6eHNpPSJodHRwOi8vd3d3LnczLm9yZy8yMDAxL1hNTFNjaGVt YS1pbnN0YW5jZSI+PE1lc3NhZ2VDb250ZW50IHhzaTp0eXBlPSJQcm9jZXNzU3RhdGVNZXNzYWdl Ij48VHlwZT5TdGFydDwvVHlwZT48VGltZT4yMDA3LTEwLTEwVDA2 2007-10-10 06:59:59,115 402261821 INFO [STDOUT] (Thread-16:) OjU5OjU4LjcyMiswODowMDwv VGltZT48U3RhdGU+PFByb2Nlc3NJRD4yNjc2Mzk3PC9Qcm9jZXNzSUQ+PFByb2Nlc3NEZWZpbml0 aW9uTmFtZT5TeXN0ZW0gVGVzdDwvUHJvY2Vzc0RlZmluaXRpb25OYW1lPjxQcm9jZXNzU3RhcnRU aW1lPjIwMDctMTAtMTBUMDY6NTk6NTguNjk4KzA4OjAwPC9Qcm9jZXNzU3RhcnRUaW1lPjxOb2Rl SUQ+MjI3NjQ4NjwvTm9kZUlEPjxEaXNwbGF5UHJpb3JpdHk+LTEwMDA8L0Rpc3BsYXlQcmlvcml0 eT48L1N0YXRlPjwvTWVzc2FnZUNvbnRlbnQ+PC9FbnZlbG9wZT4= |!%><!%N|-5|!%><!%S|T|!%>) from [] 2007-10-10 06:59:59,115 402261821 WARN [org.hibernate.engine.StatefulPersistenceContext.ProxyWarnLog] (pool-3-thread-3:) Narrowing proxy to class org.jbpm.graph.node.State - this operation breaks == 2007-10-10 06:59:59,129 402261835 INFO [SequoiaControllerProxy] (ClientNotifForwarder-1:) Got backend notification Disabled backend : sequoia:type=VirtualDataBase.Backend,VirtualDataBase=vieo_ccs,name=vieo_ccs_1 Any help or suggestions greatly appreciated Cheers Dave Cawthorn
<<winmail.dat>>
_______________________________________________ Sequoia mailing list [email protected] https://forge.continuent.org/mailman/listinfo/sequoia
