[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:
Blocks
is blocked by MODPERMS-148 RMB 33 and Vert.x 4.0.3 Closed
is blocked by MODPERMS-149 change RMB version to 33-pre1 Closed
Relates
relates to RMB-840 IllegalStateException in handleClosed... Closed
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:

  • mod-permissions is pinned to snapshot build 109 for 'testing' builds on a folio-infrastructure branch FOLIO-3144-pin-mod-perms configured in the Jenkins jobs that build folio-testing-backend and folio-testing-core-backend.
  • mod-permissions is pinned to snapshot build 109 for 'snapshot' builds in the install-extras.json file on the snapshot branch of platform-core and platform-complete.
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 RMB-840 Closed

Comment by Jakub Skoczen [ 10/May/21 ]

John Malconian Once MODPERMS-149 Closed is complete you can unpin the mod-permissions build.

Comment by Adam Dickmeiss [ 10/May/21 ]

MODPERMS-149 Closed done.

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.

Generated at Thu Feb 08 23:25:57 UTC 2024 using Jira 1001.0.0-SNAPSHOT#100246-sha1:7a5c50119eb0633d306e14180817ddef5e80c75d.