[FOLIO-3144] build-platform-complete-snapshot job failure Created: 05/May/21 Updated: 11/May/21 Resolved: 11/May/21 |
|
| Status: | Closed |
| Project: | FOLIO |
| Components: | None |
| Affects versions: | None |
| Fix versions: | None |
| Type: | Bug | Priority: | TBD |
| Reporter: | John Malconian | Assignee: | John Malconian |
| Resolution: | Done | Votes: | 0 |
| Labels: | None | ||
| Remaining Estimate: | Not Specified | ||
| Time Spent: | Not Specified | ||
| Original estimate: | Not Specified | ||
| Issue links: |
|
||||||||||||||||||||
| Sprint: | DevOps Sprint 114, DevOps Sprint 113 | ||||||||||||||||||||
| Development Team: | FOLIO DevOps | ||||||||||||||||||||
| Description |
|
The build-platform-complete-snapshot has had two consecutive build failures executing the 'Get patron groups' task in the 'set-patron-group' folio-ansible role. The error indicates a possible connection timeout: TASK [set-patron-group : Get patron groups] ************************************
fatal: [10.36.1.189]: FAILED! => {"changed": false, "content": "", "elapsed": 30, "msg": "Status code was -1 and not [200]: Connection failure: timed out", "redirected": false, "status": -1, "url": "http://10.36.1.189:9130/groups"}
PLAY RECAP *********************************************************************
10.36.1.189 : ok=124 changed=57 unreachable=0 failed=1 skipped=23 rescued=0 ignored=0
localhost : ok=7 changed=2 unreachable=0 failed=0 skipped=1 rescued=0 ignored=0
FATAL: command execution failed
hudson.AbortException: Ansible playbook execution failed
at org.jenkinsci.plugins.ansible.AnsiblePlaybookBuilder.perform(AnsiblePlaybookBuilder.java:262)
at org.jenkinsci.plugins.ansible.workflow.AnsiblePlaybookStep$AnsiblePlaybookExecution.run(AnsiblePlaybookStep.java:430)
at org.jenkinsci.plugins.ansible.workflow.AnsiblePlaybookStep$AnsiblePlaybookExecution.run(AnsiblePlaybookStep.java:351)
at org.jenkinsci.plugins.workflow.steps.AbstractSynchronousNonBlockingStepExecution$1$1.call(AbstractSynchronousNonBlockingStepExecution.java:47)
at hudson.security.ACL.impersonate2(ACL.java:449)
at hudson.security.ACL.impersonate(ACL.java:461)
at org.jenkinsci.plugins.workflow.steps.AbstractSynchronousNonBlockingStepExecution$1.run(AbstractSynchronousNonBlockingStepExecution.java:44)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
|
| Comments |
| Comment by John Malconian [ 05/May/21 ] |
|
Going to try an r5.2xlarge instance type which has double the RAM of m5.2xlarge. It appears there is very little free memory available on the ec2 instance when this task is executed. |
| Comment by John Malconian [ 05/May/21 ] |
|
Not an issue with the instance type. Investigating latest mod-permissions snapshot build 110. Call to /groups endpoint hangs. Okapi log: 2021-05-05T18:53:23,370 INFO ProxyContext 742892/groups;310449/perms REQ 172.17.0.50:48022 diku GET /perms/users mod-authtoken-2.8.0-SNAPSHOT.89 mod-permissions-5.14.0-SNAPSHOT.110 2021-05-05T18:53:23,371 INFO ProxyContext 742892/groups;310449/perms RES 202 510us mod-authtoken-2.8.0-SNAPSHOT.89 http://10.36.1.21:9178/perms/users?query=userId==2cd135d8-1742-5d3d-810a-aa1dbd0cf48f 2021-05-05T18:53:23,372 INFO DockerModuleHandle mod-permissions-5.14.0-SNAPSHOT.110 18:53:23 [] [] [] [] INFO RestRouting invoking getPermsUsers 2021-05-05T18:53:23,373 INFO DockerModuleHandle mod-permissions-5.14.0-SNAPSHOT.110 [Wed May 05 18:53:23 GMT 2021] org.folio.cql2pgjson.CQL2PgJSON INFO loadDbSchema: Loaded templates/db_scripts/schema.json OK |
| Comment by John Malconian [ 05/May/21 ] |
|
This is the query that hangs: curl -D - -w '\n' -H 'Content-Type: application/json' -H 'x-okapi-tenant: diku' -H "x-okapi-token: $OKAPI_TOKEN" 10.36.1.21:9130/groups All module containers running. |
| Comment by John Malconian [ 05/May/21 ] |
|
Okapi log for same query on folio-snapshot with mod-permissions snapshot build #109: 2021-05-05T19:05:32,106 INFO ProxyContext 513176/groups REQ 10.36.10.100:35070 diku GET /groups mod-users-17.4.0-SNAPSHOT.160 2021-05-05T19:05:32,107 INFO DockerModuleHandle mod-users-17.4.0-SNAPSHOT.160 May 05, 2021 7:05:32 PM org.folio.cql2pgjson.CQL2PgJSON loadDbSchema 2021-05-05T19:05:32,107 INFO DockerModuleHandle mod-users-17.4.0-SNAPSHOT.160 INFO: loadDbSchema: Loaded templates/db_scripts/schema.json OK 2021-05-05T19:05:32,107 INFO DockerModuleHandle mod-users-17.4.0-SNAPSHOT.160 19:05:32 INFO CQLWrapper NONE >>> SQL: null >>>LIMIT 10 OFFSET 0 2021-05-05T19:05:32,108 INFO ProxyContext 513176/groups RES 200 2053us mod-users-17.4.0-SNAPSHOT.160 http://10.36.1.187:9135/groups 2021-05-05T19:05:32,108 INFO DockerModuleHandle mod-users-17.4.0-SNAPSHOT.160 19:05:32 INFO LogUtil org.folio.rest.RestVerticle start invoking getGroups 2021-05-05T19:05:32,108 INFO DockerModuleHandle mod-users-17.4.0-SNAPSHOT.160 19:05:32 INFO LogUtil 10.36.1.187:48158 GET /groups null HTTP_1_1 200 1117 1 tid=diku OK |
| Comment by John Malconian [ 05/May/21 ] |
|
mod-permssions snapshot log (Build 110): 17:46:49 [] [] [] [] INFO CQLWrapper CRITERION >>> SQL: WHERE (jsonb->>'permissionName') = 'module.search.enabled' >>>WHERE (jsonb->>'permissionName') = 'module.search.enabled' 17:46:49 [] [] [] [] INFO CQLWrapper CRITERION >>> SQL: WHERE (jsonb->>'permissionName') = 'module.search.enabled' >>>WHERE (jsonb->>'permissionName') = 'module.search.enabled' 17:46:49 [] [] [] [] INFO PermsAPI Performing ADD operation on GRANTED_TO of permission module.search.enabled with value 821f9f0b-7c65-4a86-924c-c0e6bb71dec0 17:46:49 [] [] [] [] INFO CQLWrapper CRITERION >>> SQL: WHERE (jsonb->>'permissionName') = 'module.search.enabled' >>>WHERE (jsonb->>'permissionName') = 'module.search.enabled' 17:46:49 [] [] [] [] INFO LogUtil null POST /perms/users/821f9f0b-7c65-4a86-924c-c0e6bb71dec0/permissions null HTTP_1_1 200 48 8 tid=diku OK 17:46:49 [] [] [] [] INFO RestRouting invoking postPermsUsersPermissionsById 17:46:49 [] [] [] [] INFO CQLWrapper CRITERION >>> SQL: WHERE id = '821f9f0b-7c65-4a86-924c-c0e6bb71dec0' >>>WHERE id = '821f9f0b-7c65-4a86-924c-c0e6bb71dec0' 17:46:49 [] [] [] [] INFO CQLWrapper CRITERION >>> SQL: WHERE (jsonb->>'permissionName') = 'ui-tags.settings' >>>WHERE (jsonb->>'permissionName') = 'ui-tags.settings' [Wed May 05 17:46:49 GMT 2021] org.folio.cql2pgjson.CQL2PgJSON INFO loadDbSchema: Loaded templates/db_scripts/schema.json OK 17:46:49 [] [] [] [] INFO CQLWrapper CQL >>> SQL: id==821f9f0b-7c65-4a86-924c-c0e6bb71dec0 >>>WHERE id='821f9f0b-7c65-4a86-924c-c0e6bb71dec0' 17:46:49 [] [] [] [] INFO CQLWrapper CRITERION >>> SQL: WHERE (jsonb->>'permissionName') = 'ui-tags.settings' >>>WHERE (jsonb->>'permissionName') = 'ui-tags.settings' 17:46:49 [] [] [] [] INFO CQLWrapper CRITERION >>> SQL: WHERE (jsonb->>'permissionName') = 'ui-tags.settings' >>>WHERE (jsonb->>'permissionName') = 'ui-tags.settings' 17:46:49 [] [] [] [] INFO PermsAPI Performing ADD operation on GRANTED_TO of permission ui-tags.settings with value 821f9f0b-7c65-4a86-924c-c0e6bb71dec0 17:46:49 [] [] [] [] INFO CQLWrapper CRITERION >>> SQL: WHERE (jsonb->>'permissionName') = 'ui-tags.settings' >>>WHERE (jsonb->>'permissionName') = 'ui-tags.settings' 17:46:49 [] [] [] [] INFO LogUtil null POST /perms/users/821f9f0b-7c65-4a86-924c-c0e6bb71dec0/permissions null HTTP_1_1 200 43 8 tid=diku OK [Wed May 05 17:47:49 GMT 2021] io.vertx.core.impl.ContextImpl SEVERE Unhandled exception java.lang.IllegalStateException at io.vertx.sqlclient.impl.pool.ConnectionPool$PooledConnection.handleClosed(ConnectionPool.java:228) at io.vertx.sqlclient.impl.SocketConnectionBase.handleClose(SocketConnectionBase.java:328) at io.vertx.sqlclient.impl.SocketConnectionBase.handleClosed(SocketConnectionBase.java:300) at io.vertx.core.net.impl.ConnectionBase.checkCloseHandler(ConnectionBase.java:383) at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:125) at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:53) at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:83) at io.vertx.core.impl.DuplicatedContext.execute(DuplicatedContext.java:199) at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:50) at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:180) at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23) at io.vertx.core.Promise.complete(Promise.java:66) at io.vertx.core.impl.future.PromiseImpl.operationComplete(PromiseImpl.java:65) at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577) at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551) at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490) at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615) at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604) at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:96) at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:78) at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:73) at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:374) at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:374) at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:134) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:418) at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81) at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:221) at io.vertx.pgclient.impl.codec.PgCodec.channelInactive(PgCodec.java:57) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901) at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:818) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:497) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:834) [Wed May 05 17:47:49 GMT 2021] io.vertx.core.impl.ContextImpl SEVERE Unhandled exception java.lang.IllegalStateException at io.vertx.sqlclient.impl.pool.ConnectionPool$PooledConnection.handleClosed(ConnectionPool.java:228) at io.vertx.sqlclient.impl.SocketConnectionBase.handleClose(SocketConnectionBase.java:328) at io.vertx.sqlclient.impl.SocketConnectionBase.handleClosed(SocketConnectionBase.java:300) at io.vertx.core.net.impl.ConnectionBase.checkCloseHandler(ConnectionBase.java:383) at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:125) at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:53) at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:83) at io.vertx.core.impl.DuplicatedContext.execute(DuplicatedContext.java:199) at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:50) at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:180) at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23) at io.vertx.core.Promise.complete(Promise.java:66) at io.vertx.core.impl.future.PromiseImpl.operationComplete(PromiseImpl.java:65) at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577) at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551) at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490) at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615) at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604) at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:96) at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:78) at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:73) at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:374) at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:374) at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:134) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:418) at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81) at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:221) at io.vertx.pgclient.impl.codec.PgCodec.channelInactive(PgCodec.java:57) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901) at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:818) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:497) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:834) [Wed May 05 17:47:49 GMT 2021] io.vertx.core.impl.ContextImpl SEVERE Unhandled exception java.lang.IllegalStateException at io.vertx.sqlclient.impl.pool.ConnectionPool$PooledConnection.handleClosed(ConnectionPool.java:228) at io.vertx.sqlclient.impl.SocketConnectionBase.handleClose(SocketConnectionBase.java:328) at io.vertx.sqlclient.impl.SocketConnectionBase.handleClosed(SocketConnectionBase.java:300) at io.vertx.core.net.impl.ConnectionBase.checkCloseHandler(ConnectionBase.java:383) at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:125) at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:53) at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:83) at io.vertx.core.impl.DuplicatedContext.execute(DuplicatedContext.java:199) at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:50) at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:180) at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23) at io.vertx.core.Promise.complete(Promise.java:66) at io.vertx.core.impl.future.PromiseImpl.operationComplete(PromiseImpl.java:65) at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577) at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551) at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490) at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615) at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604) at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:96) at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:78) at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:73) at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:374) at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:374) at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:134) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:418) at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81) at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:221) at io.vertx.pgclient.impl.codec.PgCodec.channelInactive(PgCodec.java:57) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901) at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:818) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:497) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:834) [Wed May 05 17:47:49 GMT 2021] io.vertx.core.impl.ContextImpl SEVERE Unhandled exception java.lang.IllegalStateException at io.vertx.sqlclient.impl.pool.ConnectionPool$PooledConnection.handleClosed(ConnectionPool.java:228) at io.vertx.sqlclient.impl.SocketConnectionBase.handleClose(SocketConnectionBase.java:328) at io.vertx.sqlclient.impl.SocketConnectionBase.handleClosed(SocketConnectionBase.java:300) at io.vertx.core.net.impl.ConnectionBase.checkCloseHandler(ConnectionBase.java:383) at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:125) at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:53) at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:83) at io.vertx.core.impl.DuplicatedContext.execute(DuplicatedContext.java:199) at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:50) at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:180) at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23) at io.vertx.core.Promise.complete(Promise.java:66) at io.vertx.core.impl.future.PromiseImpl.operationComplete(PromiseImpl.java:65) at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577) at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551) at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490) at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615) at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604) at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:96) at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:78) at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:73) at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:374) at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:374) at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:134) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:418) at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81) at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:221) at io.vertx.pgclient.impl.codec.PgCodec.channelInactive(PgCodec.java:57) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901) at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:818) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:497) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:834) [Wed May 05 17:47:49 GMT 2021] io.vertx.core.impl.ContextImpl SEVERE Unhandled exception java.lang.IllegalStateException at io.vertx.sqlclient.impl.pool.ConnectionPool$PooledConnection.handleClosed(ConnectionPool.java:228) at io.vertx.sqlclient.impl.SocketConnectionBase.handleClose(SocketConnectionBase.java:328) at io.vertx.sqlclient.impl.SocketConnectionBase.handleClosed(SocketConnectionBase.java:300) at io.vertx.core.net.impl.ConnectionBase.checkCloseHandler(ConnectionBase.java:383) at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:125) at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:53) at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:83) at io.vertx.core.impl.DuplicatedContext.execute(DuplicatedContext.java:199) at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:50) at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:180) at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23) at io.vertx.core.Promise.complete(Promise.java:66) at io.vertx.core.impl.future.PromiseImpl.operationComplete(PromiseImpl.java:65) at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:577) at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:551) at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:490) at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:615) at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:604) at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:96) at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:78) at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:73) at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:374) at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:374) at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:134) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:418) at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81) at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:221) at io.vertx.pgclient.impl.codec.PgCodec.channelInactive(PgCodec.java:57) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901) at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:818) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:497) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:834) 17:47:50 [] [] [] [] INFO RestRouting invoking getPermsUsers [Wed May 05 17:47:50 GMT 2021] org.folio.cql2pgjson.CQL2PgJSON INFO loadDbSchema: Loaded templates/db_scripts/schema.json OK 17:48:19 [] [] [] [] INFO RestRouting invoking getPermsPermissions 17:48:19 [] [] [] [] INFO PermsAPI Generating cql to request rows from table 'permissions' with query '((permissionName=="SYS#mod-circulation-21.0.0-SNAPSHOT.843#/circulation/loan-scheduled-notices-processing#[POST]")) AND (dummy==false)' [Wed May 05 17:48:19 GMT 2021] org.folio.cql2pgjson.CQL2PgJSON INFO loadDbSchema: Loaded templates/db_scripts/schema.json OK 17:53:19 [] [] [] [] INFO RestRouting invoking getPermsPermissions 17:53:19 [] [] [] [] INFO PermsAPI Generating cql to request rows from table 'permissions' with query '((permissionName=="SYS#mod-circulation-21.0.0-SNAPSHOT.843#/circulation/loan-scheduled-notices-processing#[POST]")) AND (dummy==false)' |
| Comment by John Malconian [ 05/May/21 ] |
|
Can confirm that the build succeeds when pinning to the previous snapshot version of mod-permissions (5.14.0-SNAPSHOT.109). Build 110 contains changes that include an RMB upgrade. I suspect the problem is related to this. Pinning reference builds to mod-permissions-5.14.0-SNAPSHOT.109 until resolved. |
| Comment by John Malconian [ 07/May/21 ] |
|
With snapshot build 111 of mod-permissions, I'm able to get further along in the build, but still having the same issue as before - just at a different stage of the build - this time a PUT on one of the /eholdings interfaces. And I see the similar 'unhandled exception' error in the log as before: [Fri May 07 14:48:43 GMT 2021] io.vertx.core.impl.ContextImpl SEVERE Unhandled exception java.lang.IllegalStateException at io.vertx.sqlclient.impl.pool.ConnectionPool$PooledConnection.handleClosed(ConnectionPool.java:228) at io.vertx.sqlclient.impl.SocketConnectionBase.handleClose(SocketConnectionBase.java:328) at io.vertx.sqlclient.impl.SocketConnectionBase.handleClosed(SocketConnectionBase.java:300) at io.vertx.core.net.impl.ConnectionBase.checkCloseHandler(ConnectionBase.java:387) at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:124) at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:54) at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:83) at io.vertx.core.impl.DuplicatedContext.execute(DuplicatedContext.java:199) at io.vertx.core.impl.future.FutureBase.emitSuccess(FutureBase.java:51) at io.vertx.core.impl.future.FutureImpl.tryComplete(FutureImpl.java:179) at io.vertx.core.impl.future.PromiseImpl.tryComplete(PromiseImpl.java:23) at io.vertx.core.Promise.complete(Promise.java:66) at io.vertx.core.impl.future.PromiseImpl.operationComplete(PromiseImpl.java:65) at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578) at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:552) at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491) at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616) at io.netty.util.concurrent.DefaultPromise.setSuccess0(DefaultPromise.java:605) at io.netty.util.concurrent.DefaultPromise.setSuccess(DefaultPromise.java:96) at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:78) at io.netty.channel.DefaultChannelPromise.setSuccess(DefaultChannelPromise.java:73) at io.vertx.core.net.impl.ConnectionBase.handleClosed(ConnectionBase.java:378) at io.vertx.core.net.impl.NetSocketImpl.handleClosed(NetSocketImpl.java:382) at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:144) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:418) at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81) at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:221) at io.vertx.pgclient.impl.codec.PgCodec.channelInactive(PgCodec.java:57) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:241) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:262) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:248) at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901) at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:819) at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164) at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:497) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:834) After restarting the mod-permissions module, calls to various module endpoints are fine. |
| Comment by John Malconian [ 07/May/21 ] |
|
For the DevOps folks:
|
| Comment by Adam Dickmeiss [ 08/May/21 ] |
|
For reports like these , would be best to get the full log. The stacktrace is all "non-FOLIO", and it is important to get the exact calls to mod-permissions and other modules.. |
| Comment by Adam Dickmeiss [ 08/May/21 ] |
|
I am able to reproduce this problem by upgrading mod-permissions on a running Vagrant box. It appears like mod-permissions already has a problem during tenant init. The install never completes and a similar stack trace is produced. |
| Comment by Adam Dickmeiss [ 08/May/21 ] |
|
mod-permissions using RMB 33.0.0 pre1 does not seem to have this issue. Build 110 is using pre2. With git bisect, found the problematic commit in RMB. See
|
| Comment by Jakub Skoczen [ 10/May/21 ] |
|
John Malconian Once
|
| Comment by Adam Dickmeiss [ 10/May/21 ] |
|
|
| Comment by John Malconian [ 10/May/21 ] |
|
Unpinned mod-permissions in folio-testing builds. Let's see how those builds go this evening. If ok, I'll unpin the snapshot builds. |
| Comment by Julian Ladisch [ 11/May/21 ] |
|
mod-permissions v5.13.2 with the fix has been released: https://github.com/folio-org/mod-permissions/releases/tag/v5.13.2 |
| Comment by John Malconian [ 11/May/21 ] |
|
mod-permissions unpinned from all reference env builds. |