boglesby commented on pull request #6835:
URL: https://github.com/apache/geode/pull/6835#issuecomment-919608865
I do see an issue when I run this test:
- 1 server
- 1 client registers interest in all keys
- 1 client does puts continuously
Cause the SecurityManager to throw an AuthenticationExpiredException after a
puts have been occurring.
Add a sleep in the PutUserCredentials cmdExecute method so that the
MessageDispatcher fails. I see an exception when the client attempts to
reconnect that I'm not sure should be happening. Its not 100% reproducible, but
it happens a lot.
I added some logging on the client and server to show the order of events.
The SecurityManager authorize method expires the credentials and throws
AuthenticationExpiredException:
```
[warn 2021/09/14 16:53:17.224 PDT server1 <Client Message Dispatcher for
boglesbymac(client-register:31501:loner):62522:364cbae6:client-register>
tid=0x48] XXX TestExpirableSecurityManager.authorize isExpired returning
isExpired=true; key=152104
```
The Message Dispatcher catches the AuthenticationExpiredException:
```
[warn 2021/09/14 16:53:17.224 PDT server1 <Client Message Dispatcher for
boglesbymac(client-register:31501:loner):62522:364cbae6:client-register>
tid=0x48] XXX MessageDispatcher.runDispatcher caught
AuthenticationExpiredException processing key=152104
```
The CacheClientUpdater.handleAuthenticate on the client sends the
AuthenticateUserOp:
```
[warn 2021/09/14 16:53:17.268 PDT client-register <Cache Client Updater
Thread on boglesbymac(server1:31479)<v81>:41001 port 62511> tid=0x1e] XXX
CacheClientUpdater.handleAuthenticate about to re-authenticate
```
The server executes the PutUserCredentials.cmdExecute:
```
[warn 2021/09/14 16:53:17.270 PDT server1 <ServerConnection on port 62511
Thread 2> tid=0x43] XXX PutUserCredentials.cmdExecute
existingUniqueId=-49945521082788877
```
I've added a sleep in PutUserCredentials.cmdExecute.
Then, I see pairs of these messages every 200ms for 5 seconds (added in the
`catch (AuthenticationExpiredException expired)` block of MessageDispatcher
runDispatcher):
```
[warn 2021/09/14 16:53:17.429 PDT server1 <Client Message Dispatcher for
boglesbymac(client-register:31501:loner):62522:364cbae6:client-register>
tid=0x48] XXX MessageDispatcher.runDispatcher caught
AuthenticationExpiredException processing key=152104
[warn 2021/09/14 16:53:17.429 PDT server1 <Client Message Dispatcher for
boglesbymac(client-register:31501:loner):62522:364cbae6:client-register>
tid=0x48] XXX MessageDispatcher.runDispatcher waiting for reauthentication
key=152104
```
After 5 seconds, the Message Dispatcher gives up and closes:
```
[warn 2021/09/14 16:53:22.289 PDT server1 <Client Message Dispatcher for
boglesbymac(client-register:31501:loner):62522:364cbae6:client-register>
tid=0x48] Client did not re-authenticate back successfully in 5065ms.
Unregister this client proxy.
[warn 2021/09/14 16:53:22.291 PDT server1 <Client Message Dispatcher for
boglesbymac(client-register:31501:loner):62522:364cbae6:client-register>
tid=0x48] ClientHealthMonitor: Unregistering client with member id
identity(127.0.0.1(client-register:31501:loner):62522:364cbae6:client-register,connection=2
due to: Unknown reason
```
The CacheClientUpdater closes on the client:
```
[info 2021/09/14 16:53:22.294 PDT client-register <Cache Client Updater
Thread on boglesbymac(server1:31479)<v81>:41001 port 62511> tid=0x1e] Primary
subscription endpoint
boglesbymac.local:62511,boglesbymac(server1:31479)<v81>:41001 crashed.
Scheduling recovery.
[info 2021/09/14 16:53:22.296 PDT client-register <Cache Client Updater
Thread on boglesbymac(server1:31479)<v81>:41001 port 62511> tid=0x1e] Cache
client updater for Queue on endpoint
boglesbymac.local:62511,boglesbymac(server1:31479)<v81>:41001 exiting.
Scheduling recovery.
```
The poolTimer sends the AuthenticateUserOp:
```
[warn 2021/09/14 16:53:22.321 PDT client-register <poolTimer-pool-3>
tid=0x1b] XXX AuthenticateUserOp.executeOn about to send op
java.lang.Exception
at
org.apache.geode.cache.client.internal.AuthenticateUserOp.executeOn(AuthenticateUserOp.java:68)
at
org.apache.geode.cache.client.internal.ConnectionFactoryImpl.authenticateIfRequired(ConnectionFactoryImpl.java:152)
at
org.apache.geode.cache.client.internal.ConnectionFactoryImpl.createClientToServerConnection(ConnectionFactoryImpl.java:120)
at
org.apache.geode.cache.client.internal.ConnectionFactoryImpl.createClientToServerConnection(ConnectionFactoryImpl.java:223)
at
org.apache.geode.cache.client.internal.pooling.ConnectionManagerImpl.createPooledConnection(ConnectionManagerImpl.java:196)
at
org.apache.geode.cache.client.internal.pooling.ConnectionManagerImpl.createPooledConnection(ConnectionManagerImpl.java:190)
at
org.apache.geode.cache.client.internal.pooling.ConnectionManagerImpl.prefillConnection(ConnectionManagerImpl.java:608)
at
org.apache.geode.cache.client.internal.pooling.ConnectionManagerImpl.prefill(ConnectionManagerImpl.java:576)
at
org.apache.geode.cache.client.internal.pooling.ConnectionManagerImpl.access$200(ConnectionManagerImpl.java:70)
at
org.apache.geode.cache.client.internal.pooling.ConnectionManagerImpl$PrefillConnectionsTask.run2(ConnectionManagerImpl.java:684)
at
org.apache.geode.cache.client.internal.PoolImpl$PoolTask.run(PoolImpl.java:1336)
The queueTimer also sends the AuthenticateUserOp:
[warn 2021/09/14 16:53:22.322 PDT client-register <queueTimer-pool1>
tid=0x1f] XXX AuthenticateUserOp.executeOn about to send op
java.lang.Exception
at
org.apache.geode.cache.client.internal.AuthenticateUserOp.executeOn(AuthenticateUserOp.java:68)
at
org.apache.geode.cache.client.internal.ConnectionFactoryImpl.authenticateIfRequired(ConnectionFactoryImpl.java:152)
at
org.apache.geode.cache.client.internal.ConnectionFactoryImpl.createClientToServerConnection(ConnectionFactoryImpl.java:120)
at
org.apache.geode.cache.client.internal.QueueManagerImpl.createNewPrimary(QueueManagerImpl.java:793)
at
org.apache.geode.cache.client.internal.QueueManagerImpl.recoverPrimary(QueueManagerImpl.java:911)
at
org.apache.geode.cache.client.internal.QueueManagerImpl.access$600(QueueManagerImpl.java:77)
at
org.apache.geode.cache.client.internal.QueueManagerImpl$RedundancySatisfierTask.run2(QueueManagerImpl.java:1448)
at
org.apache.geode.cache.client.internal.PoolImpl$PoolTask.run(PoolImpl.java:1336)
```
The server processes both of these AuthenticateUserOps and returns the
unique ids:
```
[warn 2021/09/14 16:53:22.323 PDT server1 <ServerConnection on port 62512
Thread 3> tid=0x51] XXX ServerConnection.setCredentials
credentials={security-username=boglesby, security-password=boglesby}
[warn 2021/09/14 16:53:22.323 PDT server1 <ServerConnection on port 62512
Thread 2> tid=0x50] XXX ServerConnection.setCredentials
credentials={security-username=boglesby, security-password=boglesby}
[warn 2021/09/14 16:53:22.325 PDT server1 <ServerConnection on port 62512
Thread 2> tid=0x50] XXX ServerConnection.setCredentials
uniqueId=858200770272636520
[warn 2021/09/14 16:53:22.325 PDT server1 <ServerConnection on port 62512
Thread 3> tid=0x51] XXX ServerConnection.setCredentials
uniqueId=-8065196947535721026
```
The client receives these unique ids:
```
[warn 2021/09/14 16:53:22.325 PDT client-register <queueTimer-pool1>
tid=0x1f] XXX AuthenticateUserOp.executeOn uniqueId=-8065196947535721026
[warn 2021/09/14 16:53:22.325 PDT client-register <poolTimer-pool-3>
tid=0x1b] XXX AuthenticateUserOp.executeOn uniqueId=858200770272636520
```
Then the queueTimer creates a new CacheClientUpdater:
```
[warn 2021/09/14 16:53:22.325 PDT client-register <queueTimer-pool1>
tid=0x1f] XXX CacheClientUpdater.<init>
[info 2021/09/14 16:53:22.346 PDT client-register <Cache Client Updater
Thread on boglesbymac(server1:31479)<v81>:41001 port 62512> tid=0x22] Cache
Client Updater Thread on boglesbymac(server1:31479)<v81>:41001 port 62512
(boglesbymac.local:62512) : ready to process messages.
```
Then, the queueTimer attempts to re-register interest, but fails due to
`AuthenticationRequiredException: Failed to find the authenticated user` on the
server:
```
[warn 2021/09/14 16:53:22.364 PDT client-register <queueTimer-pool1>
tid=0x1f] QueueManagerImpl failed to recover interest to server
boglesbymac.local:62512
org.apache.geode.cache.client.ServerOperationException: remote server on
boglesbymac(client-register:31501:loner):62522:364cbae6:client-register:
org.apache.geode.security.AuthenticationRequiredException: Failed to find the
authenticated user.
at
org.apache.geode.cache.client.internal.OpExecutorImpl.handleException(OpExecutorImpl.java:559)
at
org.apache.geode.cache.client.internal.OpExecutorImpl.handleException(OpExecutorImpl.java:623)
at
org.apache.geode.cache.client.internal.OpExecutorImpl.handleException(OpExecutorImpl.java:512)
at
org.apache.geode.cache.client.internal.OpExecutorImpl.executeOn(OpExecutorImpl.java:475)
at
org.apache.geode.cache.client.internal.OpExecutorImpl.executeOn(OpExecutorImpl.java:486)
at
org.apache.geode.cache.client.internal.PoolImpl.executeOn(PoolImpl.java:857)
at
org.apache.geode.cache.client.internal.RegisterInterestOp.executeOn(RegisterInterestOp.java:103)
at
org.apache.geode.cache.client.internal.ServerRegionProxy.registerInterestOn(ServerRegionProxy.java:496)
at
org.apache.geode.cache.client.internal.QueueManagerImpl.recoverSingleKey(QueueManagerImpl.java:1190)
at
org.apache.geode.cache.client.internal.QueueManagerImpl.recoverSingleRegion(QueueManagerImpl.java:1158)
at
org.apache.geode.cache.client.internal.QueueManagerImpl.recoverSingleList(QueueManagerImpl.java:1103)
at
org.apache.geode.cache.client.internal.QueueManagerImpl.recoverInterestList(QueueManagerImpl.java:1223)
at
org.apache.geode.cache.client.internal.QueueManagerImpl.recoverAllInterestTypes(QueueManagerImpl.java:1237)
at
org.apache.geode.cache.client.internal.QueueManagerImpl.recoverInterest(QueueManagerImpl.java:1069)
at
org.apache.geode.cache.client.internal.QueueManagerImpl.recoverPrimary(QueueManagerImpl.java:928)
at
org.apache.geode.cache.client.internal.QueueManagerImpl.access$600(QueueManagerImpl.java:77)
at
org.apache.geode.cache.client.internal.QueueManagerImpl$RedundancySatisfierTask.run2(QueueManagerImpl.java:1448)
Caused by: org.apache.geode.security.AuthenticationRequiredException: Failed
to find the authenticated user.
at
org.apache.geode.internal.security.IntegratedSecurityService.getSubject(IntegratedSecurityService.java:123)
at
org.apache.geode.internal.security.IntegratedSecurityService.authorize(IntegratedSecurityService.java:249)
at
org.apache.geode.internal.security.IntegratedSecurityService.authorize(IntegratedSecurityService.java:244)
at
org.apache.geode.internal.security.IntegratedSecurityService.authorize(IntegratedSecurityService.java:230)
at
org.apache.geode.internal.cache.tier.sockets.command.RegisterInterest61.cmdExecute(RegisterInterest61.java:174)
at
org.apache.geode.internal.cache.tier.sockets.BaseCommand.execute(BaseCommand.java:184)
```
The server disconnects the client:
```
[warn 2021/09/14 16:53:22.365 PDT server1 <ServerConnection on port 62512
Thread 3> tid=0x51] Server connection from
[identity(127.0.0.1(client-register:31501:loner):62522:364cbae6:client-register,connection=2;
port=62544]: connection disconnect detected by EOF.
```
There are several additional retries to create the CacheClientUpdater after
this that fail.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
