Neo4j recv_time_out hint

[jogi.kalpeshn]

When creating a new connection, the Python driver receives a "recv_time_out" hint. After reviewing the driver code, it appears that this hint is used as the socket timeout. Consequently, connections in connection pools are closing after this timeout period.

Is this the expected behavior? Can the "recv_time_out" be increased? Ideally, I want my connections to remain active and only close after being idle for 60 minutes. Could anyone guide me on whether I'm missing something or how to achieve this?

==========================Connection creation=====================================
2024-06-19T11:59:08.897828780Z DEBUG:neo4j.io:[#0000]  C: <OPEN> *.*.*.*:7687
2024-06-19T11:59:08.921408401Z DEBUG:neo4j.io:[#9CD8]  C: <MAGIC> 0x6060B017
2024-06-19T11:59:08.921461001Z DEBUG:neo4j.io:[#9CD8]  C: <HANDSHAKE> 0x00040405 0x00020404 0x00000104 0x00000003
2024-06-19T11:59:08.927347532Z DEBUG:neo4j.io:[#9CD8]  S: <HANDSHAKE> 0x00000305
2024-06-19T11:59:08.927593033Z DEBUG:neo4j.io:[#9CD8]  C: HELLO {'user_agent': 'neo4j-python/5.21.0 Python/3.12.4-final-0 (linux)', 'bolt_agent': {'product': 'neo4j-python/5.21.0', 'platform': 'Linux 5.15.153.1-1.cm2; x86_64', 'language': 'Python/3.12.4-final-0', 'language_details': 'CPython; 3.12.4-final-0 (main, Jun 13 2024 05:37:23) [GCC 12.2.0]'}}
2024-06-19T11:59:08.927901835Z DEBUG:neo4j.io:[#9CD8]  _: <CONNECTION> client state: CONNECTED > AUTHENTICATION
2024-06-19T11:59:08.927918435Z DEBUG:neo4j.io:[#9CD8]  C: LOGON {'scheme': 'basic', 'principal': '****', 'credentials': '*******'}
2024-06-19T11:59:08.928057835Z DEBUG:neo4j.io:[#9CD8]  _: <CONNECTION> client state: AUTHENTICATION > READY
2024-06-19T11:59:08.929294242Z DEBUG:neo4j.io:[#9CD8]  S: SUCCESS {'server': 'Neo4j/5.11.0', 'connection_id': 'bolt-1699', 'hints': {'connection.recv_timeout_seconds': 120}}
==========================Connection creation=====================================

==========================Connection in use=====================================
2024-06-19T11:59:10.756618441Z DEBUG:neo4j.pool:[#0000]  _: <POOL> acquire direct connection, access_mode='WRITE', database=None
2024-06-19T11:59:10.756656541Z DEBUG:neo4j.pool:[#9CD8]  _: <POOL> picked existing connection bolt-1699
2024-06-19T11:59:10.756662341Z DEBUG:neo4j.pool:[#9CD8]  _: <POOL> checked re_auth auth=None updated=False force=False
2024-06-19T11:59:10.756673141Z DEBUG:neo4j.pool:[#9CD8]  _: <POOL> handing out existing connection
2024-06-19T11:59:10.772047021Z DEBUG:neo4j.io:[#9CD8]  _: <CONNECTION> client state: TX_READY_OR_TX_STREAMING > READY
2024-06-19T11:59:10.773481728Z DEBUG:neo4j.io:[#9CD8]  S: SUCCESS {'bookmark': 'FB:kcwQyzGFXGtVSCmo/9KgfNyUisoAAZNCkA=='}
2024-06-19T11:59:10.773517728Z DEBUG:neo4j.io:[#9CD8]  _: <CONNECTION> server state: TX_READY_OR_TX_STREAMING > READY
2024-06-19T11:59:10.773582928Z DEBUG:neo4j.pool:[#9CD8]  _: <POOL> released bolt-1699
==========================Connection in use=====================================

==========================Connection closed unexpectedly=====================================
2024-06-19T12:04:01.982656645Z DEBUG:neo4j.pool:[#0000]  _: <POOL> acquire direct connection, access_mode='WRITE', database=None
2024-06-19T12:04:01.982756344Z DEBUG:neo4j.pool:[#9CD8]  _: <POOL> picked existing connection bolt-1699
2024-06-19T12:04:01.982766744Z DEBUG:neo4j.pool:[#9CD8]  _: <POOL> checked re_auth auth=None updated=False force=False
2024-06-19T12:04:01.982771244Z DEBUG:neo4j.pool:[#9CD8]  _: <POOL> handing out existing connection
2024-06-19T12:04:01.982906343Z DEBUG:neo4j.io:[#9CD8]  C: BEGIN {'bookmarks': ['FB:kcwQyzGFXGtVSCmo/9KgfNyUisoAAZNCkA==']}
2024-06-19T12:04:01.983081442Z DEBUG:neo4j.io:[#9CD8]  _: <CONNECTION> client state: READY > TX_READY_OR_TX_STREAMING
2024-06-19T12:04:01.984509830Z DEBUG:neo4j.io:[#9CD8]  C: RUN "MATCH (n:CalculationNode {project: 'DEMO_Transact_C'}) RETURN properties(n) LIMIT 25" {} {}
2024-06-19T12:04:01.984670528Z DEBUG:neo4j.io:[#9CD8]  C: PULL {'n': 1000}

2024-06-19T12:06:02.037746789Z DEBUG:neo4j.io:[#9CD8]  _: <CONNECTION> error: TimeoutError('timed out')
2024-06-19T12:06:02.037816789Z ERROR:neo4j.io:Failed to read from defunct connection IPv4Address(('xyz.eastus.cloudapp.azure.com', 7687)) (ResolvedIPv4Address(('*.*.*.*', 7687)))
2024-06-19T12:06:02.037823989Z DEBUG:neo4j.io:[#9CD8]  C: <CLOSE>
2024-06-19T12:06:02.037976390Z DEBUG:neo4j.pool:[#9CD8]  _: <POOL> released bolt-1699
2024-06-19T12:06:02.038255991Z WARNING:neo4j.pool:Transaction failed and will be retried in 0.9578847926699836s (Failed to read from defunct connection IPv4Address(('*.*.*.*', 7687)) (ResolvedIPv4Address(('*.*.*.*', 7687))))
2024-06-19T12:06:02.996632060Z DEBUG:neo4j.pool:[#0000]  _: <POOL> acquire direct connection, access_mode='WRITE', database=None
2024-06-19T12:06:02.996677860Z DEBUG:neo4j.pool:[#9CD8]  _: <POOL> found unhealthy connection bolt-1699 (closed=True, defunct=True, stale=False, in_use=True)
2024-06-19T12:06:02.996683960Z DEBUG:neo4j.pool:[#9CD8]  _: <POOL> remove connection from pool IPv4Address(('codescout-neo4j-dev.eastus.cloudapp.azure.com', 7687)) bolt-1699
2024-06-19T12:06:02.996693860Z DEBUG:neo4j.pool:[#0000]  _: <POOL> trying to hand out new connection
==========================Connection closed=====================================

I found following in neo4j python driver code

github link

[rouven_bauer]

To get this out of the way: recv_time_out can be increased by changing the server configurations:

• config_server.bolt.connection_keep_alive
• config_server.bolt.connection_keep_alive_probes

But I think you misinterpreted the driver code. The recv_time_out gets set as the socket timeout. That does not mean that after recv_time_out the socket gets closed no matter what. What this means is that when reading/writing from/to that socket takes longer thatn recv_time_out, the socket is considered dead. This application-level keep-alive mechanism helps detect network issues where poorly behaving network infrastructure is involved. E.g., there proxies that close TCP connections without notifying the two ends the proxy was connecting.

However, there is a driver setting that will close connections not in use if they have been opened too long ago: max_connection_lifetime.
This is set to 1h by default.

There also is liveness_check_timeout which might be helpful.

Having a look at the log excerpt, assuming you've not cut out anything on connection #9CD8 between the PULL and the TimeoutError, you'll see that the server has not responded withing 2 minutes. It should have! If not with records from the query than with a NOOP message just to show it's still listening on the other side of the connection. This is intended behavior. And since the server didn't reply, the driver has to assume that either the connection died or the server is helplessly overwhelmed.

For more resilience, I recommend you use an API that implements retires (such as session.execute_read/session.execute_write or driver.execute_query). If not that, you could roll your own retry mechanism on retryable errors (s. here and here), which is more difficult to get right.

[jogi.kalpeshn]

Thank you for your detailed response. It was indeed misunderstanding from my side that it is happening because of recv_time_out. Thanks for pointing that out. Infact, i am getting this value as 120 seconds and program is erroring out exactly after 5 minutes.

Having said that, I am still experiencing issues with connections closing after 5 minutes despite having the max_connection_lifetime set to its default value. The connections work fine up to 4 minutes but fail after 5 minutes.

I have gone through following article and used program attached there to find out root cause.

How to handle Session Expired Errors while connecting to Neo4j Aura

Here is the code I am using for establishing connections and setting configurations:

 with (driver = neo4j.driver(NEO4J_URI, neo4j.auth.basic(NEO4J_USER, NEO4J_PASS), {
            maxConnectionPoolSize: 1,
            // The logging block code 
            logging: {
                // setting the logging level to debug, possible options 'debug', 'info', 'warn', 'error'
                level: 'debug',
                // the logger function. It will receive log level and the message to be logged.
                logger: (level, message) => {
                    console[level].call(console, `${level.toUpperCase()} ${message}`)
                }
            }
         
        })) {
            with (session = driver.session({ database: 'neo4j', defaultAccessMode: neo4j.session.READ })) {
                with (txc = session.beginTransaction()) {
                    txc.run("RETURN 1 AS n")

Below are the elaborated log entries for the connection working fine till 4 minutes (240 seconds):

2024-06-25 10:39:48.431956 This script will check if connections idle after the following lifetime values are still usable(seconds):
                 240, 300

2024-06-25 10:39:48.432580 Attempting to connect to neo4j://<neo4j_FQDN>:7687

2024-06-25 10:39:48.432804 Checking connection lifetime of 240 seconds
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,433  [#0000]  _: <POOL> created, routing address IPv4Address(('<neo4j_FQDN>', 7687))
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,433  [#0000]  _: <POOL> acquire routing connection, access_mode='READ', database='neo4j'
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,433  [#0000]  _: <ROUTING> checking table freshness (readonly=True): table expired=True, has_server_for_mode=False, table routers={IPv4Address(('<neo4j_FQDN>', 7687))} => False
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,433  [#0000]  _: <POOL> attempting to update routing table from IPv4Address(('<neo4j_FQDN>', 7687))
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,433  [#0000]  _: <RESOLVE> in: <neo4j_FQDN>:7687
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,439  [#0000]  _: <RESOLVE> dns resolver out: <IP_ADDR>:7687
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,439  [#0000]  _: <POOL> _acquire router connection, database='neo4j', address=ResolvedIPv4Address(('<IP_ADDR>', 7687))
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,439  [#0000]  _: <POOL> trying to hand out new connection
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,439  [#0000]  C: <OPEN> <IP_ADDR>:7687
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,464  [#D244]  C: <MAGIC> 0x6060B017
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,465  [#D244]  C: <HANDSHAKE> 0x00040405 0x00020404 0x00000104 0x00000003
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,488  [#D244]  S: <HANDSHAKE> 0x00000405
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,488  [#D244]  C: HELLO {'user_agent': 'neo4j-python/5.19.0 Python/3.10.13-final-0 (linux)', 'routing': {'address': '<neo4j_FQDN>:7687'}, 'bolt_agent': {'product': 'neo4j-python/5.19.0', 'platform': 'Linux 6.5.0-1021-azure; x86_64', 'language': 'Python/3.10.13-final-0', 'language_details': 'CPython; 3.10.13-final-0 (main, Mar 21 2024 17:51:02) [GCC 9.4.0]'}}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,488  [#D244]  _: <CONNECTION> client state: CONNECTED > AUTHENTICATION
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,488  [#D244]  C: LOGON {'scheme': 'basic', 'principal': 'neo4j', 'credentials': '*******'}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,489  [#D244]  _: <CONNECTION> client state: AUTHENTICATION > READY
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,513  [#D244]  S: SUCCESS {'server': 'Neo4j/5.19.0', 'connection_id': 'bolt-854', 'hints': {'connection.recv_timeout_seconds': 120}}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,513  [#D244]  _: <CONNECTION> server state: CONNECTED > AUTHENTICATION
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,513  [#D244]  S: SUCCESS {}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,513  [#D244]  _: <CONNECTION> server state: AUTHENTICATION > READY
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,514  [#D244]  C: ROUTE {'address': '<neo4j_FQDN>:7687'} () {'db': 'neo4j'}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,537  [#D244]  S: SUCCESS {'rt': {'servers': [{'addresses': ['<neo4j_FQDN>:7687'], 'role': 'WRITE'}, {'addresses': ['<neo4j_FQDN>:7687'], 'role': 'READ'}, {'addresses': ['<neo4j_FQDN>:7687'], 'role': 'ROUTE'}], 'ttl': 300, 'db': 'neo4j'}}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,538  [#D244]  _: <POOL> released bolt-854
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,538  [#0000]  _: <ROUTING> updated table=RoutingTable(database='neo4j' routers={IPv4Address(('<neo4j_FQDN>', 7687))}, readers={IPv4Address(('<neo4j_FQDN>', 7687))}, writers={IPv4Address(('<neo4j_FQDN>', 7687))}, last_updated_time=1982.864543171, ttl=300)
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,538  [#0000]  _: <POOL> update routing table from address=ResolvedIPv4Address(('<IP_ADDR>', 7687)) (RoutingTable(database='neo4j' routers={IPv4Address(('<neo4j_FQDN>', 7687))}, readers={IPv4Address(('<neo4j_FQDN>', 7687))}, writers={IPv4Address(('<neo4j_FQDN>', 7687))}, last_updated_time=1982.864543171, ttl=300))
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,538  [#0000]  _: <POOL> acquire address, database='neo4j' address=IPv4Address(('<neo4j_FQDN>', 7687))
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,538  [#0000]  _: <POOL> trying to hand out new connection
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,538  [#0000]  _: <RESOLVE> in: <neo4j_FQDN>:7687
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,540  [#0000]  _: <RESOLVE> dns resolver out: <IP_ADDR>:7687
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,541  [#0000]  C: <OPEN> <IP_ADDR>:7687
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,562  [#D252]  C: <MAGIC> 0x6060B017
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,562  [#D252]  C: <HANDSHAKE> 0x00040405 0x00020404 0x00000104 0x00000003
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,583  [#D252]  S: <HANDSHAKE> 0x00000405
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,583  [#D252]  C: HELLO {'user_agent': 'neo4j-python/5.19.0 Python/3.10.13-final-0 (linux)', 'routing': {'address': '<neo4j_FQDN>:7687'}, 'bolt_agent': {'product': 'neo4j-python/5.19.0', 'platform': 'Linux 6.5.0-1021-azure; x86_64', 'language': 'Python/3.10.13-final-0', 'language_details': 'CPython; 3.10.13-final-0 (main, Mar 21 2024 17:51:02) [GCC 9.4.0]'}}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,583  [#D252]  _: <CONNECTION> client state: CONNECTED > AUTHENTICATION
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,584  [#D252]  C: LOGON {'scheme': 'basic', 'principal': 'neo4j', 'credentials': '*******'}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,584  [#D252]  _: <CONNECTION> client state: AUTHENTICATION > READY
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,605  [#D252]  S: SUCCESS {'server': 'Neo4j/5.19.0', 'connection_id': 'bolt-855', 'hints': {'connection.recv_timeout_seconds': 120}}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,605  [#D252]  _: <CONNECTION> server state: CONNECTED > AUTHENTICATION
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,606  [#D252]  S: SUCCESS {}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,606  [#D252]  _: <CONNECTION> server state: AUTHENTICATION > READY
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,606  [#D252]  C: BEGIN {'mode': 'r', 'db': 'neo4j'}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,606  [#D252]  _: <CONNECTION> client state: READY > TX_READY_OR_TX_STREAMING
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,627  [#D252]  S: SUCCESS {}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,627  [#D252]  _: <CONNECTION> server state: READY > TX_READY_OR_TX_STREAMING
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,627  [#D252]  C: RUN 'RETURN 1 AS n' {} {}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,627  [#D252]  C: PULL {'n': 1000}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:39:48,649  [#D252]  S: SUCCESS {'t_first': 1, 'fields': ['n'], 'qid': 0}
2024-06-25 10:39:48.649296 Initial connection Successful. Sleeping for 4 minutes ...
2024-06-25 10:40:48.708936 Still running. Sleeping for 3 more minute(s) ...
2024-06-25 10:41:48.767131 Still running. Sleeping for 2 more minute(s) ...
2024-06-25 10:42:48.826472 Still running. Sleeping for 1 more minute(s) ...
2024-06-25 10:43:48.885922 Awake now. Checking the connection ...
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,886  [#D252]  C: RUN 'RETURN 1 AS n' {} {}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,886  [#D252]  C: PULL {'n': 1000}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,886  [#D252]  S: RECORD * 1
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,887  [#D252]  S: SUCCESS {'type': 'r', 't_last': 0, 'db': 'neo4j'}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,908  [#D252]  S: SUCCESS {'t_first': 0, 'fields': ['n'], 'qid': 1}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,909  [#D252]  S: RECORD * 1
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,909  [#D252]  S: SUCCESS {'type': 'r', 't_last': 0, 'db': 'neo4j'}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,909  [#D252]  C: COMMIT
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,909  [#D252]  _: <CONNECTION> client state: TX_READY_OR_TX_STREAMING > READY
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,932  [#D252]  S: SUCCESS {'bookmark': 'FB:kcwQwnqeYaVaR+Ou4O2V5AMTvskP6ZA='}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,932  [#D252]  _: <CONNECTION> server state: TX_READY_OR_TX_STREAMING > READY
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,932  [#D252]  _: <POOL> released bolt-855
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,933  [#0000]  _: <POOL> close
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,933  [#D244]  C: GOODBYE
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,933  [#D244]  C: <CLOSE>
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,933  [#D252]  C: GOODBYE
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,933  [#D252]  C: <CLOSE>
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,933  [#0000]  _: <POOL> close
2024-06-25 10:43:48.933997 The connection was valid after 240 seconds of idle time...

As you can see, the connection works perfectly until the 4-minute mark (240 seconds)

And here are the log entries for the connection resulting in failure after 5 minutes:(300 seconds)

2024-06-25 10:43:48.934329 Checking connection lifetime of 300 seconds
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,934  [#0000]  _: <POOL> created, routing address IPv4Address(('<neo4j_FQDN>', 7687))
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,934  [#0000]  _: <POOL> acquire routing connection, access_mode='READ', database='neo4j'
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,935  [#0000]  _: <ROUTING> checking table freshness (readonly=True): table expired=True, has_server_for_mode=False, table routers={IPv4Address(('<neo4j_FQDN>', 7687))} => False
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,935  [#0000]  _: <POOL> attempting to update routing table from IPv4Address(('<neo4j_FQDN>', 7687))
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,935  [#0000]  _: <RESOLVE> in: <neo4j_FQDN>:7687
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,938  [#0000]  _: <RESOLVE> dns resolver out: <IP_ADDR>:7687
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,939  [#0000]  _: <POOL> _acquire router connection, database='neo4j', address=ResolvedIPv4Address(('<IP_ADDR>', 7687))
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,939  [#0000]  _: <POOL> trying to hand out new connection
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,939  [#0000]  C: <OPEN> <IP_ADDR>:7687
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,958  [#9CA4]  C: <MAGIC> 0x6060B017
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,958  [#9CA4]  C: <HANDSHAKE> 0x00040405 0x00020404 0x00000104 0x00000003
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,976  [#9CA4]  S: <HANDSHAKE> 0x00000405
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,977  [#9CA4]  C: HELLO {'user_agent': 'neo4j-python/5.19.0 Python/3.10.13-final-0 (linux)', 'routing': {'address': '<neo4j_FQDN>:7687'}, 'bolt_agent': {'product': 'neo4j-python/5.19.0', 'platform': 'Linux 6.5.0-1021-azure; x86_64', 'language': 'Python/3.10.13-final-0', 'language_details': 'CPython; 3.10.13-final-0 (main, Mar 21 2024 17:51:02) [GCC 9.4.0]'}}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,977  [#9CA4]  _: <CONNECTION> client state: CONNECTED > AUTHENTICATION
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,977  [#9CA4]  C: LOGON {'scheme': 'basic', 'principal': 'neo4j', 'credentials': '*******'}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,977  [#9CA4]  _: <CONNECTION> client state: AUTHENTICATION > READY
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,996  [#9CA4]  S: SUCCESS {'server': 'Neo4j/5.19.0', 'connection_id': 'bolt-856', 'hints': {'connection.recv_timeout_seconds': 120}}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,996  [#9CA4]  _: <CONNECTION> server state: CONNECTED > AUTHENTICATION
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,997  [#9CA4]  S: SUCCESS {}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,997  [#9CA4]  _: <CONNECTION> server state: AUTHENTICATION > READY
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:48,997  [#9CA4]  C: ROUTE {'address': '<neo4j_FQDN>:7687'} () {'db': 'neo4j'}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,016  [#9CA4]  S: SUCCESS {'rt': {'servers': [{'addresses': ['<neo4j_FQDN>:7687'], 'role': 'WRITE'}, {'addresses': ['<neo4j_FQDN>:7687'], 'role': 'READ'}, {'addresses': ['<neo4j_FQDN>:7687'], 'role': 'ROUTE'}], 'ttl': 300, 'db': 'neo4j'}}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,016  [#9CA4]  _: <POOL> released bolt-856
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,017  [#0000]  _: <ROUTING> updated table=RoutingTable(database='neo4j' routers={IPv4Address(('<neo4j_FQDN>', 7687))}, readers={IPv4Address(('<neo4j_FQDN>', 7687))}, writers={IPv4Address(('<neo4j_FQDN>', 7687))}, last_updated_time=2223.343346232, ttl=300)
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,017  [#0000]  _: <POOL> update routing table from address=ResolvedIPv4Address(('<IP_ADDR>', 7687)) (RoutingTable(database='neo4j' routers={IPv4Address(('<neo4j_FQDN>', 7687))}, readers={IPv4Address(('<neo4j_FQDN>', 7687))}, writers={IPv4Address(('<neo4j_FQDN>', 7687))}, last_updated_time=2223.343346232, ttl=300))
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,017  [#0000]  _: <POOL> acquire address, database='neo4j' address=IPv4Address(('<neo4j_FQDN>', 7687))
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,017  [#0000]  _: <POOL> trying to hand out new connection
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,017  [#0000]  _: <RESOLVE> in: <neo4j_FQDN>:7687
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,021  [#0000]  _: <RESOLVE> dns resolver out: <IP_ADDR>:7687
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,021  [#0000]  C: <OPEN> <IP_ADDR>:7687
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,043  [#9CB4]  C: <MAGIC> 0x6060B017
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,043  [#9CB4]  C: <HANDSHAKE> 0x00040405 0x00020404 0x00000104 0x00000003
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,064  [#9CB4]  S: <HANDSHAKE> 0x00000405
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,064  [#9CB4]  C: HELLO {'user_agent': 'neo4j-python/5.19.0 Python/3.10.13-final-0 (linux)', 'routing': {'address': '<neo4j_FQDN>:7687'}, 'bolt_agent': {'product': 'neo4j-python/5.19.0', 'platform': 'Linux 6.5.0-1021-azure; x86_64', 'language': 'Python/3.10.13-final-0', 'language_details': 'CPython; 3.10.13-final-0 (main, Mar 21 2024 17:51:02) [GCC 9.4.0]'}}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,065  [#9CB4]  _: <CONNECTION> client state: CONNECTED > AUTHENTICATION
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,065  [#9CB4]  C: LOGON {'scheme': 'basic', 'principal': 'neo4j', 'credentials': '*******'}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,065  [#9CB4]  _: <CONNECTION> client state: AUTHENTICATION > READY
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,086  [#9CB4]  S: SUCCESS {'server': 'Neo4j/5.19.0', 'connection_id': 'bolt-857', 'hints': {'connection.recv_timeout_seconds': 120}}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,086  [#9CB4]  _: <CONNECTION> server state: CONNECTED > AUTHENTICATION
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,087  [#9CB4]  S: SUCCESS {}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,087  [#9CB4]  _: <CONNECTION> server state: AUTHENTICATION > READY
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,087  [#9CB4]  C: BEGIN {'mode': 'r', 'db': 'neo4j'}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,087  [#9CB4]  _: <CONNECTION> client state: READY > TX_READY_OR_TX_STREAMING
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,108  [#9CB4]  S: SUCCESS {}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,109  [#9CB4]  _: <CONNECTION> server state: READY > TX_READY_OR_TX_STREAMING
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,109  [#9CB4]  C: RUN 'RETURN 1 AS n' {} {}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,109  [#9CB4]  C: PULL {'n': 1000}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:43:49,130  [#9CB4]  S: SUCCESS {'t_first': 0, 'fields': ['n'], 'qid': 0}
2024-06-25 10:43:49.131059 Initial connection Successful. Sleeping for 5 minutes ...
2024-06-25 10:44:49.190208 Still running. Sleeping for 4 more minute(s) ...
2024-06-25 10:45:49.245722 Still running. Sleeping for 3 more minute(s) ...
2024-06-25 10:46:49.301758 Still running. Sleeping for 2 more minute(s) ...
2024-06-25 10:47:49.358960 Still running. Sleeping for 1 more minute(s) ...
2024-06-25 10:48:49.417797 Awake now. Checking the connection ...
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:48:49,418  [#9CB4]  C: RUN 'RETURN 1 AS n' {} {}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:48:49,419  [#9CB4]  C: PULL {'n': 1000}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:48:49,419  [#9CB4]  S: RECORD * 1
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:48:49,425  [#9CB4]  S: SUCCESS {'type': 'r', 't_last': 0, 'db': 'neo4j'}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:50:49,521  [#9CB4]  _: <CONNECTION> error: TimeoutError('timed out')
[ERROR   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:50:49,522  Failed to read from defunct connection IPv4Address(('<neo4j_FQDN>', 7687)) (ResolvedIPv4Address(('<IP_ADDR>', 7687)))
ERROR:neo4j.io:Failed to read from defunct connection IPv4Address(('<neo4j_FQDN>', 7687)) (ResolvedIPv4Address(('<IP_ADDR>', 7687)))
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:50:49,522  [#9CB4]  C: <CLOSE>
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:50:49,522  [#0000]  _: <POOL> deactivating address IPv4Address(('<neo4j_FQDN>', 7687))
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:50:49,522  [#0000]  _: <POOL> table={'neo4j': RoutingTable(database='neo4j' routers={}, readers={}, writers={}, last_updated_time=2223.343346232, ttl=300)}
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:50:49,522  [#9CB4]  _: <POOL> released bolt-857
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:50:49,522  [#0000]  _: <POOL> close
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:50:49,522  [#9CA4]  C: GOODBYE
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:50:49,523  [#9CA4]  C: <CLOSE>
2024-06-25 10:50:49.523183 Session Expired for connection with idle time of 300 seconds 
[DEBUG   ] [Thread 130688205369984] [TASK NONE] 2024-06-25 10:50:49,523  [#0000]  _: <POOL> close
2024-06-25 10:50:49.523453 The connection FAILED after 300 seconds of idle time...
2024-06-25 10:50:49.523661 Recommended Connection lifetime : 230 seconds or lesser
2024-06-25 10:50:49.523751 The longest running valid connection was 240 seconds old.
2024-06-25 10:50:49.523829 The recommended value is 10 seconds lesser than this 

Based on your suggestion, I expected NOOP messages to keep the connection alive, but I haven't observed any such messages in the logs.

Could you provide further guidance on how to ensure connections remain active for the desired period and how to properly configure the NOOP messages if necessary? Additionally, is there any other configuration or driver setting that I might be overlooking?

Thank you for your assistance!

[rouven_bauer]

First a few questions: 1. Why is that code snippet looking more like JS than Python? I'm confused. 2. The logs indicate you downgraded the Python driver from 5.21 to 5.19. Any particular reason for that? N.B.: I don't anticipate your problems would go away if you upgrade.

The reason you're not seeing any NOOP messages is the there is no pending request left that the server could insert the NOOP into. The server only can send NOOPs while the driver is actively waiting for a response. E.g., between RECORD messages. However, the first RETURN 1 AS n almost instantly finishes and the server writes the RECORD and all necessary SUCCESS messages to the wire finishing off the request.

The output confirms that there is something on the network that kills connections idling for more than 5 minutes. To avoid running into that, I recommend you

1. make sure you're not running any single transaction that holds onto the connection for more than 5 minutes without sending any work to the DBMS (that shouldn't be too hard I reckon).
2. Set the liveness_check_timeout to something just shy of 5 minutes (e.g., 4.5 minutes). That way, the driver will notice dead connections and discard them instead using them to back transactions.

Ideally, you'd not have to do any of this, but figure out what network component causes the issue and fix that. But I'm aware that one often isn't in control of the networking infrastructure. Especially not so when using cloud providers.

[jogi.kalpeshn]

I have updated the Python driver to version 5.22.0. Below is the Python script and the corresponding logs. In my previous post, I mistakenly copy-pasted the Nodejs script because I also rewrote the same program in NodeJs to check this issue. I wanted to confirm whether underlying network is causing problems or it is something else. Later in this post are my findings from Node.js: this problem does not occur in Node.js. Both scripts are running on the same machine (specifically, GitHub Codespaces).
PYTHON:

def checkConnLife(NEO4J_URI,NEO4J_USER,NEO4J_PASS,connIdleTime):    
    idlePass = False
    try:
        with neo4j.GraphDatabase.driver(NEO4J_URI, auth=(NEO4J_USER, NEO4J_PASS),
                                        max_connection_pool_size=1,
                                        max_connection_lifetime=3600, 
                                        keep_alive=True ) as driver:
            with driver.session(database="neo4j",default_access_mode=neo4j.READ_ACCESS) as session:
                with session.begin_transaction() as tx:
                    tx.run("RETURN 1 AS n")
                    if connIdleTime > 120:
                        sleepMinsLeft = int(connIdleTime/60)  
                        sleepSecondsLeft = connIdleTime%60
                        customLogger(f'{GREEN}Initial connection Successful. Sleeping for {sleepMinsLeft} minutes ...{RESET}')
                        while sleepMinsLeft>0:
                            sleep(60)#Sleeping for sleepMin x minutes
                            sleepMinsLeft -=1
                            if sleepMinsLeft>0:
                                print(dt.now(),f'Still running. Sleeping for {sleepMinsLeft} more minute(s) ...')
                        sleep(sleepSecondsLeft)
                    else: 
                        customLogger(f'{GREEN}Initial connection Successful. Sleeping for {connIdleTime} seconds ...{RESET}')
                        sleep(connIdleTime)
                    customLogger('Awake now. Checking the connection ...')
                    tx.run("RETURN 1 AS n")
                    idlePass = True
            
    except neo4j.exceptions.SessionExpired:
        customLogger(f'{RED}Session Expired for connection with idle time of {connIdleTime} seconds {RESET}');
        idlePass = False
    #except neo4j.exceptions.SessionError:
    #    customLogger("Session Error for connection with idle time of ");
    #    idlePass = False        
    except Exception as e:
        customLogger(f'{RED}Different Error encountered. Exiting\nError: {e}{RESET}') 
        exit
    finally:
        driver.close()
    return idlePass

PYTHON LOGS

2024-06-27 13:09:23.617230 The connection was valid after 240 seconds of idle time...
2024-06-27 13:09:23.619609 Checking connection lifetime of 300 seconds
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,620  [#0000]  _: <POOL> created, routing address IPv4Address(('<FQDN>', 7687))
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,620  [#0000]  _: <POOL> acquire routing connection, access_mode='READ', database='neo4j'
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,620  [#0000]  _: <ROUTING> checking table freshness (readonly=True): table expired=True, has_server_for_mode=False, table routers={IPv4Address(('<FQDN>', 7687))} => False
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,620  [#0000]  _: <POOL> attempting to update routing table from IPv4Address(('<FQDN>', 7687))
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,620  [#0000]  _: <RESOLVE> in: <FQDN:7687>
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,626  [#0000]  _: <RESOLVE> dns resolver out: <IPADRESS:7687>
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,626  [#0000]  _: <POOL> _acquire router connection, database='neo4j', address=ResolvedIPv4Address(('<ip_address>', 7687))
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,628  [#0000]  _: <POOL> trying to hand out new connection
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,628  [#0000]  C: <OPEN> <IPADRESS:7687>
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,647  [#D0BE]  C: <MAGIC> 0x6060B017
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,647  [#D0BE]  C: <HANDSHAKE> 0x00050505 0x00020404 0x00000104 0x00000003
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,668  [#D0BE]  S: <HANDSHAKE> 0x00000405
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,669  [#D0BE]  C: HELLO {'user_agent': 'neo4j-python/5.22.0 Python/3.10.13-final-0 (linux)', 'routing': {'address': '<FQDN:7687>'}, 'bolt_agent': {'product': 'neo4j-python/5.22.0', 'platform': 'Linux 6.5.0-1022-azure; x86_64', 'language': 'Python/3.10.13-final-0', 'language_details': 'CPython; 3.10.13-final-0 (main, Mar 21 2024 17:51:02) [GCC 9.4.0]'}}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,669  [#D0BE]  _: <CONNECTION> client state: CONNECTED > AUTHENTICATION
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,669  [#D0BE]  C: LOGON {'scheme': 'basic', 'principal': 'neo4j', 'credentials': '*******'}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,669  [#D0BE]  _: <CONNECTION> client state: AUTHENTICATION > READY
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,688  [#D0BE]  S: SUCCESS {'server': 'Neo4j/5.19.0', 'connection_id': 'bolt-2261', 'hints': {'connection.recv_timeout_seconds': 120}}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,688  [#D0BE]  _: <CONNECTION> server state: CONNECTED > AUTHENTICATION
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,688  [#D0BE]  S: SUCCESS {}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,688  [#D0BE]  _: <CONNECTION> server state: AUTHENTICATION > READY
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,689  [#D0BE]  C: ROUTE {'address': '<FQDN:7687>'} () {'db': 'neo4j'}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,707  [#D0BE]  S: SUCCESS {'rt': {'servers': [{'addresses': ['<FQDN:7687>'], 'role': 'WRITE'}, {'addresses': ['<FQDN:7687>'], 'role': 'READ'}, {'addresses': ['<FQDN:7687>'], 'role': 'ROUTE'}], 'ttl': 300, 'db': 'neo4j'}}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,708  [#D0BE]  _: <POOL> released bolt-2261
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,708  [#0000]  _: <ROUTING> updated table=RoutingTable(database='neo4j' routers={IPv4Address(('<FQDN>', 7687))}, readers={IPv4Address(('<FQDN>', 7687))}, writers={IPv4Address(('<FQDN>', 7687))}, last_updated_time=530.489955987, ttl=300)
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,708  [#0000]  _: <POOL> update routing table from address=ResolvedIPv4Address(('<ip_address>', 7687)) (RoutingTable(database='neo4j' routers={IPv4Address(('<FQDN>', 7687))}, readers={IPv4Address(('<FQDN>', 7687))}, writers={IPv4Address(('<FQDN>', 7687))}, last_updated_time=530.489955987, ttl=300))
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,708  [#0000]  _: <POOL> acquire address, database='neo4j' address=IPv4Address(('<FQDN>', 7687))
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,708  [#0000]  _: <POOL> trying to hand out new connection
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,708  [#0000]  _: <RESOLVE> in: <FQDN:7687>
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,712  [#0000]  _: <RESOLVE> dns resolver out: <IPADRESS:7687>
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,712  [#0000]  C: <OPEN> <IPADRESS:7687>
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,736  [#D0CC]  C: <MAGIC> 0x6060B017
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,737  [#D0CC]  C: <HANDSHAKE> 0x00050505 0x00020404 0x00000104 0x00000003
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,761  [#D0CC]  S: <HANDSHAKE> 0x00000405
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,761  [#D0CC]  C: HELLO {'user_agent': 'neo4j-python/5.22.0 Python/3.10.13-final-0 (linux)', 'routing': {'address': '<FQDN:7687>'}, 'bolt_agent': {'product': 'neo4j-python/5.22.0', 'platform': 'Linux 6.5.0-1022-azure; x86_64', 'language': 'Python/3.10.13-final-0', 'language_details': 'CPython; 3.10.13-final-0 (main, Mar 21 2024 17:51:02) [GCC 9.4.0]'}}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,761  [#D0CC]  _: <CONNECTION> client state: CONNECTED > AUTHENTICATION
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,762  [#D0CC]  C: LOGON {'scheme': 'basic', 'principal': 'neo4j', 'credentials': '*******'}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,762  [#D0CC]  _: <CONNECTION> client state: AUTHENTICATION > READY
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,787  [#D0CC]  S: SUCCESS {'server': 'Neo4j/5.19.0', 'connection_id': 'bolt-2262', 'hints': {'connection.recv_timeout_seconds': 120}}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,787  [#D0CC]  _: <CONNECTION> server state: CONNECTED > AUTHENTICATION
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,788  [#D0CC]  S: SUCCESS {}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,788  [#D0CC]  _: <CONNECTION> server state: AUTHENTICATION > READY
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,789  [#D0CC]  C: BEGIN {'mode': 'r', 'db': 'neo4j'}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,789  [#D0CC]  _: <CONNECTION> client state: READY > TX_READY_OR_TX_STREAMING
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,814  [#D0CC]  S: SUCCESS {}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,814  [#D0CC]  _: <CONNECTION> server state: READY > TX_READY_OR_TX_STREAMING
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,814  [#D0CC]  C: RUN 'RETURN 1 AS n' {} {}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,815  [#D0CC]  C: PULL {'n': 1000}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:09:23,839  [#D0CC]  S: SUCCESS {'t_first': 1, 'fields': ['n'], 'qid': 0}
2024-06-27 13:09:23.839535 Initial connection Successful. Sleeping for 5 minutes ...
2024-06-27 13:10:23.898485 Still running. Sleeping for 4 more minute(s) ...
2024-06-27 13:11:23.958400 Still running. Sleeping for 3 more minute(s) ...
2024-06-27 13:12:24.001123 Still running. Sleeping for 2 more minute(s) ...
2024-06-27 13:13:24.059294 Still running. Sleeping for 1 more minute(s) ...
2024-06-27 13:14:24.117213 Awake now. Checking the connection ...
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:14:24,117  [#D0CC]  C: RUN 'RETURN 1 AS n' {} {}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:14:24,117  [#D0CC]  C: PULL {'n': 1000}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:14:24,118  [#D0CC]  S: RECORD * 1
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:14:24,118  [#D0CC]  S: SUCCESS {'type': 'r', 't_last': 0, 'db': 'neo4j'}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:16:24,215  [#D0CC]  _: <CONNECTION> error: TimeoutError('timed out')
[ERROR   ] [Thread 139861339075200] [Task None] 2024-06-27 13:16:24,215  Failed to read from defunct connection IPv4Address(('<FQDN>', 7687)) (ResolvedIPv4Address(('<ip_address>', 7687)))
ERROR:neo4j.io:Failed to read from defunct connection IPv4Address(('<FQDN>', 7687)) (ResolvedIPv4Address(('<ip_address>', 7687)))
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:16:24,215  [#D0CC]  C: <CLOSE>
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:16:24,215  [#0000]  _: <POOL> deactivating address IPv4Address(('<FQDN>', 7687))
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:16:24,215  [#0000]  _: <POOL> table={'neo4j': RoutingTable(database='neo4j' routers={}, readers={}, writers={}, last_updated_time=530.489955987, ttl=300)}
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:16:24,216  [#D0CC]  _: <POOL> released bolt-2262
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:16:24,216  [#0000]  _: <POOL> close
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:16:24,217  [#D0BE]  C: GOODBYE
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:16:24,217  [#D0BE]  C: <CLOSE>
2024-06-27 13:16:24.217857 Session Expired for connection with idle time of 300 seconds 
[DEBUG] [Thread 139861339075200] [Task None] 2024-06-27 13:16:24,218  [#0000]  _: <POOL> close
2024-06-27 13:16:24.218628 The connection FAILED after 300 seconds of idle time...
2024-06-27 13:16:24.218851 Recommended Connection lifetime : 230 seconds or lesser
2024-06-27 13:16:24.219144 The longest running valid connection was 240 seconds old.
2024-06-27 13:16:24.219426 The recommended value is 10 seconds lesser than this 

NODE:

async function checkConnLife(NEO4J_URI, NEO4J_USER, NEO4J_PASS, connIdleTime) {
    var idlePass = false
    try {
        with (driver = neo4j.driver(NEO4J_URI, neo4j.auth.basic(NEO4J_USER, NEO4J_PASS), {
            maxConnectionPoolSize: 1,
            logging: {
                level: 'debug',
                logger: (level, message) => {
                    console[level].call(console, `${level.toUpperCase()} ${(new Date()).toISOString()} ${message}`)
                }
            }
         
        })) {
            with (session = driver.session({ database: 'neo4j', defaultAccessMode: neo4j.session.READ })) {
                with (txc = session.beginTransaction()) {
                    txc.run("RETURN 1 AS n")
                    if (connIdleTime > 120) {
                        let sleepMinsLeft = connIdleTime / 60
                        let sleepSecondsLeft = connIdleTime % 60
                        console.log(chalk.yellow(new Date().toISOString() +' Initial connection Successful. Sleeping for ' + sleepMinsLeft + ' minutes ...'))
                        while (sleepMinsLeft > 0) {
                            await sleep(60)
                            sleepMinsLeft -= 1
                            if (sleepMinsLeft > 0)
                                console.log(new Date().toISOString() + 'Still running. Sleeping for ' + sleepMinsLeft + ' more minute(s) ...')
                        }
                        await sleep(sleepSecondsLeft)
                    }
                    else {
                        console.log(chalk.yellow('Initial connection Successful. Sleeping for ' + connIdleTime + ' seconds ...'))
                        await sleep(connIdleTime)
                    }
                    console.log(chalk.yellow(new Date().toISOString() +' Awake now. Checking the connection ...'))
                    txc.run("RETURN 1 AS n")
                    console.log(new Date().toISOString() +" connection is active")
                    idlePass = true
                }
            }
        }
    }
    catch (e) {
        console.log(e)
        console.log(chalk.yellow('Session Expired for connection with idle time of ' + connIdleTime + ' seconds '));
        idlePass = false
    }
    finally {
        //console.log("done")
        //driver.close()
    }
    return idlePass
}

NODE LOGS:

Checking connection lifetime of 300 seconds
INFO 2024-06-27T14:36:29.291Z Routing driver 0 created for server address <FQDN>:7687
2024-06-27T14:36:29.294Z Initial connection Successful. Sleeping for 5 minutes ...
INFO 2024-06-27T14:36:29.295Z Routing table is stale for database: "neo4j" and access mode: "READ": RoutingTable[database=neo4j, expirationTime=0, currentTime=1719498989295, routers=[], readers=[], writers=[]]
DEBUG 2024-06-27T14:36:29.356Z Connection [0][] created towards <FQDN>:7687(<ip_address>)
DEBUG 2024-06-27T14:36:29.357Z Connection [0][] C: HELLO {"user_agent":"neo4j-javascript/5.21.0","bolt_agent":{"product":"neo4j-javascript/5.21.0","platform":"linux 6.5.0-1022-azure; x64","language_details":"Node/20.11.1 (v8 11.3.244.8-node.17)"},"routing":{"address":"<FQDN>:7687"}}
DEBUG 2024-06-27T14:36:29.359Z Connection [0][] C: LOGON { ... }
DEBUG 2024-06-27T14:36:29.383Z Connection [0][] S: SUCCESS {"signature":112,"fields":[{"server":"Neo4j/5.19.0","connection_id":"bolt-2296","hints":{"connection.recv_timeout_seconds":{"low":120,"high":0}}}]}
DEBUG 2024-06-27T14:36:29.384Z Connection [0][] S: SUCCESS {"signature":112,"fields":[{}]}
DEBUG 2024-06-27T14:36:29.385Z Connection [0][bolt-2296] created for the pool <FQDN>:7687
DEBUG 2024-06-27T14:36:29.385Z Connection [0][bolt-2296] acquired from the pool <FQDN>:7687
DEBUG 2024-06-27T14:36:29.386Z Connection [0][bolt-2296] C: ROUTE {"address":"<FQDN>:7687"} [] {"db":"neo4j"}
DEBUG 2024-06-27T14:36:29.409Z Connection [0][bolt-2296] S: SUCCESS {"signature":112,"fields":[{"rt":{"servers":[{"addresses":["<FQDN>:7687"],"role":"WRITE"},{"addresses":["<FQDN>:7687"],"role":"READ"},{"addresses":["<FQDN>:7687"],"role":"ROUTE"}],"ttl":{"low":300,"high":0},"db":"neo4j"}}]}
DEBUG 2024-06-27T14:36:29.411Z Connection [0][bolt-2296] released to the pool <FQDN>:7687
INFO 2024-06-27T14:36:29.412Z Updated routing table RoutingTable[database=neo4j, expirationTime=1719499289410, currentTime=1719498989412, routers=[<FQDN>:7687], readers=[<FQDN>:7687], writers=[<FQDN>:7687]]
DEBUG 2024-06-27T14:36:29.413Z Connection [0][bolt-2296] acquired from the pool <FQDN>:7687
DEBUG 2024-06-27T14:36:29.413Z Connection [0][bolt-2296] acquired from the pool <FQDN>:7687
DEBUG 2024-06-27T14:36:29.414Z Connection [0][bolt-2296] C: BEGIN {"db":"neo4j","mode":"r"}
DEBUG 2024-06-27T14:36:29.415Z Connection [0][bolt-2296] C: RUN RETURN 1 AS n {} {}
DEBUG 2024-06-27T14:36:29.416Z Connection [0][bolt-2296] C: PULL {"n":{"low":1000,"high":0}}
DEBUG 2024-06-27T14:36:29.437Z Connection [0][bolt-2296] S: SUCCESS {"signature":112,"fields":[{}]}
DEBUG 2024-06-27T14:36:29.460Z Connection [0][bolt-2296] S: SUCCESS {"signature":112,"fields":[{"t_first":{"low":0,"high":0},"fields":["n"],"qid":{"low":0,"high":0}}]}
DEBUG 2024-06-27T14:36:29.460Z Connection [0][bolt-2296] S: RECORD {"signature":113,"fields":[[{"low":1,"high":0}]]}
DEBUG 2024-06-27T14:36:29.460Z Connection [0][bolt-2296] S: SUCCESS {"signature":112,"fields":[{"type":"r","t_last":{"low":0,"high":0},"db":"neo4j"}]}
2024-06-27T14:37:29.323ZStill running. Sleeping for 4 more minute(s) ...
2024-06-27T14:38:29.379ZStill running. Sleeping for 3 more minute(s) ...
2024-06-27T14:39:29.438ZStill running. Sleeping for 2 more minute(s) ...
2024-06-27T14:40:29.489ZStill running. Sleeping for 1 more minute(s) ...
2024-06-27T14:41:29.548Z Awake now. Checking the connection ...
2024-06-27T14:41:29.549Z connection is active
The connection was valid after 300 seconds of idle time...
DEBUG 2024-06-27T14:41:29.549Z Connection [0][bolt-2296] C: RUN RETURN 1 AS n {} {}
DEBUG 2024-06-27T14:41:29.549Z Connection [0][bolt-2296] C: PULL {"n":{"low":1000,"high":0}}
DEBUG 2024-06-27T14:41:29.573Z Connection [0][bolt-2296] S: SUCCESS {"signature":112,"fields":[{"t_first":{"low":1,"high":0},"fields":["n"],"qid":{"low":1,"high":0}}]}
DEBUG 2024-06-27T14:41:29.573Z Connection [0][bolt-2296] S: RECORD {"signature":113,"fields":[[{"low":1,"high":0}]]}
DEBUG 2024-06-27T14:41:29.573Z Connection [0][bolt-2296] S: SUCCESS {"signature":112,"fields":[{"type":"r","t_last":{"low":0,"high":0},"db":"neo4j"}]}
 Checking connection lifetime of 600 seconds
INFO 2024-06-27T14:41:31.552Z Routing driver 1 created for server address <FQDN>:7687
2024-06-27T14:41:31.552Z Initial connection Successful. Sleeping for 10 minutes ...
INFO 2024-06-27T14:41:31.553Z Routing table is stale for database: "neo4j" and access mode: "READ": RoutingTable[database=neo4j, expirationTime=0, currentTime=1719499291553, routers=[], readers=[], writers=[]]
DEBUG 2024-06-27T14:41:31.604Z Connection [1][] created towards <FQDN>:7687(<ip_address>)
DEBUG 2024-06-27T14:41:31.605Z Connection [1][] C: HELLO {"user_agent":"neo4j-javascript/5.21.0","bolt_agent":{"product":"neo4j-javascript/5.21.0","platform":"linux 6.5.0-1022-azure; x64","language_details":"Node/20.11.1 (v8 11.3.244.8-node.17)"},"routing":{"address":"<FQDN>:7687"}}
DEBUG 2024-06-27T14:41:31.605Z Connection [1][] C: LOGON { ... }
DEBUG 2024-06-27T14:41:31.628Z Connection [1][] S: SUCCESS {"signature":112,"fields":[{"server":"Neo4j/5.19.0","connection_id":"bolt-2297","hints":{"connection.recv_timeout_seconds":{"low":120,"high":0}}}]}
DEBUG 2024-06-27T14:41:31.629Z Connection [1][] S: SUCCESS {"signature":112,"fields":[{}]}
DEBUG 2024-06-27T14:41:31.629Z Connection [1][bolt-2297] created for the pool <FQDN>:7687
DEBUG 2024-06-27T14:41:31.629Z Connection [1][bolt-2297] acquired from the pool <FQDN>:7687
DEBUG 2024-06-27T14:41:31.630Z Connection [1][bolt-2297] C: ROUTE {"address":"<FQDN>:7687"} [] {"db":"neo4j"}
DEBUG 2024-06-27T14:41:31.653Z Connection [1][bolt-2297] S: SUCCESS {"signature":112,"fields":[{"rt":{"servers":[{"addresses":["<FQDN>:7687"],"role":"WRITE"},{"addresses":["<FQDN>:7687"],"role":"READ"},{"addresses":["<FQDN>:7687"],"role":"ROUTE"}],"ttl":{"low":300,"high":0},"db":"neo4j"}}]}
DEBUG 2024-06-27T14:41:31.653Z Connection [1][bolt-2297] released to the pool <FQDN>:7687
INFO 2024-06-27T14:41:31.654Z Updated routing table RoutingTable[database=neo4j, expirationTime=1719499591653, currentTime=1719499291654, routers=[<FQDN>:7687], readers=[<FQDN>:7687], writers=[<FQDN>:7687]]
DEBUG 2024-06-27T14:41:31.654Z Connection [1][bolt-2297] acquired from the pool <FQDN>:7687
DEBUG 2024-06-27T14:41:31.654Z Connection [1][bolt-2297] acquired from the pool <FQDN>:7687
DEBUG 2024-06-27T14:41:31.654Z Connection [1][bolt-2297] C: BEGIN {"db":"neo4j","mode":"r"}
DEBUG 2024-06-27T14:41:31.654Z Connection [1][bolt-2297] C: RUN RETURN 1 AS n {} {}
DEBUG 2024-06-27T14:41:31.655Z Connection [1][bolt-2297] C: PULL {"n":{"low":1000,"high":0}}
DEBUG 2024-06-27T14:41:31.677Z Connection [1][bolt-2297] S: SUCCESS {"signature":112,"fields":[{}]}
DEBUG 2024-06-27T14:41:31.700Z Connection [1][bolt-2297] S: SUCCESS {"signature":112,"fields":[{"t_first":{"low":1,"high":0},"fields":["n"],"qid":{"low":0,"high":0}}]}
DEBUG 2024-06-27T14:41:31.700Z Connection [1][bolt-2297] S: RECORD {"signature":113,"fields":[[{"low":1,"high":0}]]}
DEBUG 2024-06-27T14:41:31.700Z Connection [1][bolt-2297] S: SUCCESS {"signature":112,"fields":[{"type":"r","t_last":{"low":0,"high":0},"db":"neo4j"}]}
2024-06-27T14:42:31.582ZStill running. Sleeping for 9 more minute(s) ...
2024-06-27T14:43:31.584ZStill running. Sleeping for 8 more minute(s) ...
2024-06-27T14:44:31.644ZStill running. Sleeping for 7 more minute(s) ...
2024-06-27T14:45:31.701ZStill running. Sleeping for 6 more minute(s) ...
2024-06-27T14:46:31.762ZStill running. Sleeping for 5 more minute(s) ...
2024-06-27T14:47:31.822ZStill running. Sleeping for 4 more minute(s) ...
2024-06-27T14:48:31.874ZStill running. Sleeping for 3 more minute(s) ...
2024-06-27T14:49:31.934ZStill running. Sleeping for 2 more minute(s) ...
2024-06-27T14:50:31.993ZStill running. Sleeping for 1 more minute(s) ...
2024-06-27T14:51:32.051Z Awake now. Checking the connection ...
2024-06-27T14:51:32.051Z connection is active
The connection was valid after 600 seconds of idle time...
DEBUG 2024-06-27T14:51:32.052Z Connection [1][bolt-2297] C: RUN RETURN 1 AS n {} {}
DEBUG 2024-06-27T14:51:32.052Z Connection [1][bolt-2297] C: PULL {"n":{"low":1000,"high":0}}
DEBUG 2024-06-27T14:51:32.075Z Connection [1][bolt-2297] S: SUCCESS {"signature":112,"fields":[{"t_first":{"low":0,"high":0},"fields":["n"],"qid":{"low":1,"high":0}}]}
DEBUG 2024-06-27T14:51:32.075Z Connection [1][bolt-2297] S: RECORD {"signature":113,"fields":[[{"low":1,"high":0}]]}
DEBUG 2024-06-27T14:51:32.075Z Connection [1][bolt-2297] S: SUCCESS {"signature":112,"fields":[{"type":"r","t_last":{"low":0,"high":0},"db":"neo4j"}]}

[jogi.kalpeshn]

I was able to reproduce this problem using the Neo4j sandbox environment (https://sandbox.neo4j.com/). I've included the Python and Node.js scripts used for testing this connection problem in the following GitHub repository:

GitHub - jogikalpesh/neo4jTest

You can find the scripts at these locations in the repository:

Node.js: [node/bin/index.js]
Python: [python/connection-test.py]

I have also included some sample logs in the repository after running these scripts against the Neo4j sandbox environment:

Node.js: [node/sample-logs/logs-28-06.log]
Python: [python/sample-logs/log-28-06.log]

When running these scripts, be sure to add values to the NEO4J_URI, NEO4J_USER, and NEO4J_PASS variables.

[rouven_bauer]

Thank you very much for providing the reproducer this is really helpful. Unfortunately, I cannot reproduce the behavior locally. Executing the Python script against a blank sandbox instance (at https://sandbox.neo4j.com/), it runs until the end:

2024-07-01 11:38:38.017279 The connection was valid after 600 seconds of idle time...

2024-07-01 11:38:38.017778 Recommended Connection lifetime : 590 seconds or lesser
2024-07-01 11:38:38.018051 The longest running valid connection was 600 seconds old.
2024-07-01 11:38:38.018281 The recommended value is 10 seconds lesser than this 

Have you tried running the JS and Python test scripts multiple times (or even at the same time) to make sure it's not just flaky? If it's consistent for you, could you do me a favor and use Wireshark to capture the network traffic between the server and the driver? If so, please make sure that:

• You provide one capture file per driver so I don't have to separate the conversations manually.
• You use a sandbox instance with a random password and delete that instance before you upload the capture as it will contain the password.