[
https://issues.apache.org/jira/browse/GEODE-10144?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17510953#comment-17510953
]
Barrett Oglesby commented on GEODE-10144:
-----------------------------------------
Even though this JIRA is resolved, I did some analysis on it.
I see whats going on in this test.
At the beginning of the test client cache operations are occurring
simultaneously with message dispatching from the server to the client.
Here is a ServerConnection processing puts:
{noformat}
[warn 2022/03/22 15:40:01.096 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX Put70.cmdExecute operation=UPDATE;
key=key50
[warn 2022/03/22 15:40:01.096 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX
SimulatedExpirationSecurityManager.authorize about to return true
[warn 2022/03/22 15:40:01.099 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX Put70.cmdExecute operation=UPDATE;
key=key51
[warn 2022/03/22 15:40:01.099 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX
SimulatedExpirationSecurityManager.authorize about to return true
[warn 2022/03/22 15:40:01.101 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX Put70.cmdExecute operation=UPDATE;
key=key52
[warn 2022/03/22 15:40:01.102 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX
SimulatedExpirationSecurityManager.authorize about to return true
[warn 2022/03/22 15:40:01.104 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX Put70.cmdExecute operation=UPDATE;
key=key53
[warn 2022/03/22 15:40:01.104 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX
SimulatedExpirationSecurityManager.authorize about to return true
[warn 2022/03/22 15:40:01.106 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX Put70.cmdExecute operation=UPDATE;
key=key54
[warn 2022/03/22 15:40:01.107 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX
SimulatedExpirationSecurityManager.authorize about to return true
{noformat}
At the same time, the Client Message Dispatcher is dispatching events to the
client:
{noformat}
[warn 2022/03/22 15:40:01.098 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher about to dispatchMessage
operation=AFTER_CREATE; key=key50
[warn 2022/03/22 15:40:01.098 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
SimulatedExpirationSecurityManager.authorize about to return true
[warn 2022/03/22 15:40:01.099 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher done dispatchMessage operation=AFTER_CREATE;
key=key50
[warn 2022/03/22 15:40:01.101 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher about to dispatchMessage
operation=AFTER_CREATE; key=key51
[warn 2022/03/22 15:40:01.101 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
SimulatedExpirationSecurityManager.authorize about to return true
[warn 2022/03/22 15:40:01.101 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher done dispatchMessage operation=AFTER_CREATE;
key=key51
[warn 2022/03/22 15:40:01.103 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher about to dispatchMessage
operation=AFTER_CREATE; key=key52
[warn 2022/03/22 15:40:01.104 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
SimulatedExpirationSecurityManager.authorize about to return true
[warn 2022/03/22 15:40:01.104 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher done dispatchMessage operation=AFTER_CREATE;
key=key52
[warn 2022/03/22 15:40:01.106 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher about to dispatchMessage
operation=AFTER_CREATE; key=key53
[warn 2022/03/22 15:40:01.106 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
SimulatedExpirationSecurityManager.authorize about to return true
[warn 2022/03/22 15:40:01.106 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher done dispatchMessage operation=AFTER_CREATE;
key=key53
{noformat}
While the Client Message Dispatcher, it requests authorization which fails.
Since the NC is not the latest version, no ClientReAuthenticateMessage is sent
to it. The dispatcher waits anyway in case another operation updates the
credentials:
{noformat}
[warn 2022/03/22 15:40:01.109 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher about to dispatchMessage
operation=AFTER_CREATE; key=key54
[warn 2022/03/22 15:40:01.110 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
SimulatedExpirationSecurityManager.authorize about to throw
AuthenticationExpiredException
[warn 2022/03/22 15:40:01.110 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher caught AuthenticationExpiredException
[warn 2022/03/22 15:40:01.110 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher skipped sending ClientReAuthenticateMessage
clientVersion=GFE 9.0
[warn 2022/03/22 15:40:01.110 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher about to wait for remainingWaitTime=5000
{noformat}
Which is exactly what happens.
Puts continue successfully:
{noformat}
[warn 2022/03/22 15:40:01.366 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX Put70.cmdExecute operation=UPDATE;
key=key212
[warn 2022/03/22 15:40:01.366 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX
SimulatedExpirationSecurityManager.authorize about to return true
[warn 2022/03/22 15:40:01.367 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX Put70.cmdExecute operation=UPDATE;
key=key213
[warn 2022/03/22 15:40:01.367 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX
SimulatedExpirationSecurityManager.authorize about to return true
[warn 2022/03/22 15:40:01.368 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX Put70.cmdExecute operation=UPDATE;
key=key214
[warn 2022/03/22 15:40:01.368 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX
SimulatedExpirationSecurityManager.authorize about to return true
{noformat}
At some point in the 5 seconds, one of the puts fails:
{noformat}
[warn 2022/03/22 15:40:01.369 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX Put70.cmdExecute operation=UPDATE;
key=key215
[warn 2022/03/22 15:40:01.369 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX
SimulatedExpirationSecurityManager.authorize about to throw
AuthenticationExpiredException
{noformat}
Which causes the credentials to be sent again:
{noformat}
[warn 2022/03/22 15:40:01.520 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX PutUserCredentials.cmdExecute
[warn 2022/03/22 15:40:01.521 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX
SimulatedExpirationSecurityManager.authenticate
[warn 2022/03/22 15:40:01.521 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX ServerConnection.putSubject
isWaitingForReAuthentication=true
{noformat}
And the waiting Client Message Dispatcher to be notified at which time it
continues processing:
{noformat}
[warn 2022/03/22 15:40:01.521 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX MessageDispatcher.notifyReAuthentication
about to notifyAll
[warn 2022/03/22 15:40:01.521 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher done waiting
[warn 2022/03/22 15:40:01.522 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher about to dispatchMessage
operation=AFTER_CREATE; key=key54
[warn 2022/03/22 15:40:01.522 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
SimulatedExpirationSecurityManager.authorize about to return true
[warn 2022/03/22 15:40:01.522 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX Put70.cmdExecute operation=UPDATE;
key=key215
[warn 2022/03/22 15:40:01.522 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 7> tid=0x50] XXX
SimulatedExpirationSecurityManager.authorize about to return true
{noformat}
This is the intended behavior. In this case, the Client Message Dispatcher
waited for ~400ms.
The problem occurs when the client operations stop. After that, the Client
Message Dispatcher waits for 5 seconds every time since there isn't any outside
operation to notify it:
{noformat}
[warn 2022/03/22 15:40:21.012 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher about to dispatchMessage
operation=AFTER_DESTROY; key=key4471
[warn 2022/03/22 15:40:21.012 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
SimulatedExpirationSecurityManager.authorize about to throw
AuthenticationExpiredException
[warn 2022/03/22 15:40:21.012 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher caught AuthenticationExpiredException
[warn 2022/03/22 15:40:21.012 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher skipped sending ClientReAuthenticateMessage
clientVersion=GFE 9.0
[warn 2022/03/22 15:40:21.012 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher about to wait for remainingWaitTime=5000
[warn 2022/03/22 15:40:26.013 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher done wait for remainingWaitTime=5000
[warn 2022/03/22 15:40:26.013 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] Client did not re-authenticate
back successfully in 5001 ms. Unregister this client proxy.
{noformat}
Then, the client reconnects:
{noformat}
[warn 2022/03/22 15:40:31.831 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 8> tid=0x54] XXX PutUserCredentials.cmdExecute
[warn 2022/03/22 15:40:31.832 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <ServerConnection
on port 58030 Thread 8> tid=0x54] XXX ServerConnection.putSubject
isWaitingForReAuthentication=false
[info 2022/03/22 15:40:31.833 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Queue
Initialization Thread 1> tid=0x45] :Cache server: Initializing primary
server-to-client communication socket:
Socket[addr=/127.0.0.1,port=58097,localport=58030]
[info 2022/03/22 15:40:31.835 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Queue
Initialization Thread 1> tid=0x45]
CacheClientProxy[identity(127.0.0.1(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS,connection=1,durableAttributes=DurableClientAttributes[id=DurableClient-1111_gem_default;
timeout=600]); port=58097; primary=true; version=GFE 9.0]: Cancelling
expiration task since the client has reconnected.
{noformat}
The default subscription ack interval in PoolFactory.cpp is 100 seconds. That
means the client only acknowledges that it received a message every 100
seconds. By contrast, in the java client, the default subscription ack interval
100 ms.
{noformat}
const std::chrono::milliseconds PoolFactory::DEFAULT_SUBSCRIPTION_ACK_INTERVAL =
std::chrono::seconds{100};
{noformat}
So, since all the messages are still on the queue, the Client Message
Dispatcher starts sending messages back at the beginning again:
{noformat}
[warn 2022/03/22 15:40:31.837 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher about to dispatchMessage
operation=AFTER_CREATE; key=key0
[warn 2022/03/22 15:40:31.837 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
SimulatedExpirationSecurityManager.authorize about to return true
[warn 2022/03/22 15:40:31.837 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher done dispatchMessage operation=AFTER_CREATE;
key=key0
[warn 2022/03/22 15:40:31.837 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher about to dispatchMessage
operation=AFTER_CREATE; key=key1
[warn 2022/03/22 15:40:31.837 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
SimulatedExpirationSecurityManager.authorize about to return true
[warn 2022/03/22 15:40:31.838 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher done dispatchMessage operation=AFTER_CREATE;
key=key1
{noformat}
It doesn't take long before SimulatedExpirationSecurityManager.authorize throws
AuthenticationExpiredException. Then the Message Dispatcher waits for 5 seconds
before continuing.
{noformat}
[warn 2022/03/22 15:41:11.862 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher about to dispatchMessage
operation=AFTER_CREATE; key=key156
[warn 2022/03/22 15:41:11.862 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
SimulatedExpirationSecurityManager.authorize about to throw
AuthenticationExpiredException
[warn 2022/03/22 15:41:11.862 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher caught AuthenticationExpiredException
[warn 2022/03/22 15:41:11.862 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher skipped sending ClientReAuthenticateMessage
clientVersion=GFE 9.0
[warn 2022/03/22 15:41:11.862 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher about to wait for remainingWaitTime=5000
[warn 2022/03/22 15:41:16.863 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] XXX
MessageDispatcher.runDispatcher done wait for remainingWaitTime=5000
[warn 2022/03/22 15:41:16.863 PDT
CqPlusAuthInitializeTest_reAuthenticateWithDurable_server_0 <Client Message
Dispatcher for
boglesbymac(default_GeodeDS:71811:loner):2:Native_oUm2Hyr5kF71811:default_GeodeDS
(DurableClient-1111_gem_default)> tid=0x51] Client did not re-authenticate
back successfully in 5001 ms. Unregister this client proxy.
{noformat}
It cycles like this for the rest of the test.
There are 34 of these 5 second waits in the latest test run.
> Regression in geode-native test
> CqPlusAuthInitializeTest.reAuthenticateWithDurable
> ----------------------------------------------------------------------------------
>
> Key: GEODE-10144
> URL: https://issues.apache.org/jira/browse/GEODE-10144
> Project: Geode
> Issue Type: Bug
> Components: client/server
> Affects Versions: 1.15.0
> Reporter: Blake Bender
> Assignee: Jinmei Liao
> Priority: Major
> Labels: blocks-1.15.0, needsTriage
> Fix For: 1.15.0
>
>
> This test is failing across the board in the `geode-native` PR pipeline.
> Main develop pipeline is green only because nothing can get through the PR
> pipeline to clear checkin gates. We have green CI runs with 1.15. build 918,
> then it started failing when we picked up build 924.
>
> [~moleske] tracked this back to this commit:
> [https://github.com/apache/geode/commit/2554f42b925f2b9b8ca7eee14c7a887436b1d9db|https://github.com/apache/geode/commit/2554f42b925f2b9b8ca7eee14c7a887436b1d9db].
> See his notes in `geode-native` PR # 947
> ([https://github.com/apache/geode-native/pull/947])
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
