Apache Geode Native Client logs show a connection pool error on starting native client

We run a native client and I have noticed a Failed to add endpoint to pool error in the cache server logs when the client is started.

I setup the logs using:

CacheFactory cacheFactory = new CacheFactory();
return cacheFactory
    .Set("log-file", "Geode.log")
    .Set("log-level", "ALL")
    .Set("name", "Dealer")
    .SetPdxReadSerialized(true)
    .Create();

The Geode.log file shows the following:

[info 2020/09/03 12:40:57.906591 GMT Daylight Time ARGO:15580 11876] ClientMetadataService started for pool MyPool2
[debug 2020/09/03 12:40:57.986018 GMT Daylight Time ARGO:15580 25428] SerializationRegistry::deserialize typeId = -1 dsCode =  1
[debug 2020/09/03 12:40:57.986095 GMT Daylight Time ARGO:15580 25428] closing the connection locator1
[debug 2020/09/03 12:40:57.986117 GMT Daylight Time ARGO:15580 25428] closing the connection locator
[fine 2020/09/03 12:40:57.986205 GMT Daylight Time ARGO:15580 25428] Created new endpoint 1.2.3.4:40404 for pool MyPool2
[error 2020/09/03 12:40:57.986256 GMT Daylight Time ARGO:15580 25428] Failed to add endpoint 1.2.3.4:40404 to pool MyPool2
[debug 2020/09/03 12:40:57.986285 GMT Daylight Time ARGO:15580 25428] ThinClientRedundancyManager::maintainRedundancyLevel(): checking redundant list, size = 0
[debug 2020/09/03 12:40:57.986303 GMT Daylight Time ARGO:15580 25428] ThinClientRedundancyManager::maintainRedundancyLevel(): finding nonredundant endpoints, size = 1
[fine 2020/09/03 12:40:57.986321 GMT Daylight Time ARGO:15580 25428] Recovering subscriptions on endpoint [1.2.3.4:40404] from pool MyPool2
[fine 2020/09/03 12:40:57.986339 GMT Daylight Time ARGO:15580 25428] TcrEndpoint::createNewConnection: connectTimeout = m_needToConnectInLock=59000000 appThreadRequest =0
[debug 2020/09/03 12:40:57.986361 GMT Daylight Time ARGO:15580 25428] Tcrconnection const isSecondary = 0 and isClientNotification = 0, this = 00000202EDBAD790,  conn ref to endopint 1
[finest 2020/09/03 12:40:57.986438 GMT Daylight Time ARGO:15580 25428] Using socket send buffer size of 64240.
[finest 2020/09/03 12:40:57.986465 GMT Daylight Time ARGO:15580 25428] Using socket receive buffer size of 64240.
[debug 2020/09/03 12:40:57.986482 GMT Daylight Time ARGO:15580 25428] Creating plain socket stream

Can someone explain why we see the error here? The code that is executed is at ThinClientPoolDM.cpp but the error does not seem to make any difference to the client, which we can see does make a connection. Though the server endpoint does not appear to be added to a pool in the error state we can see a fine message almost immediately after saying recovering subscriptions on endpoint and it's the same endpoint.

Solution

There was a longstanding bug in this code causing it to log a failure here on success and vice-versa, which is most likely what you're hitting. This was fixed as part of PR #588 for GEODE-7930, on 4/6/2020. Please see if you have this fix in your local repo and reply if you do and are still hitting the issue.