search

neo4j / neo4j-python-driver

Neo4j Bolt driver for Python
https://neo4j.com/docs/api/python-driver/current/
Other
898 stars 186 forks source link

Logging overhaul #849

Closed robsdedude closed 1 year ago

robsdedude commented 1 year ago
robsdedude commented 1 year ago

Here is what some logging looked like before

[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,530  [#0000]  C: <NEO4J POOL> routing address IPv4Address(('localhost', 7687))
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,530  [#0000]  C: <ROUTING TABLE ENSURE FRESH> {None: RoutingTable(database=None routers={IPv4Address(('localhost', 7687))}, readers={}, writers={}, last_updated_time=3961.23487757, ttl=0)}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,530  [#0000]  C: <ROUTING> Checking table freshness (readonly=False)
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,531  [#0000]  C: <ROUTING> Table expired=True
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,531  [#0000]  C: <ROUTING> Table routers={IPv4Address(('localhost', 7687))}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,531  [#0000]  C: <ROUTING> Table has_server_for_mode=False
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,531  Attempting to update routing table from IPv4Address(('localhost', 7687))
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,531  [#0000]  C: <RESOLVE> localhost:7687
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,534  [#0000]  C: <OPEN> 127.0.0.1:7687
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,536  [#D73A]  C: <MAGIC> 0x6060B017
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,536  [#D73A]  C: <HANDSHAKE> 0x00000005 0x00020404 0x00000104 0x00000003
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,536  [#D73A]  S: <HANDSHAKE> 0x00000404
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,537  [#D73A]  C: HELLO {'user_agent': 'neo4j-python/5.2.dev0 Python/3.7.13-final-0 (linux)', 'routing': {'address': 'localhost:7687'}, 'patch_bolt': ['utc'], 'scheme': 'basic', 'principal': 'neo4j', 'credentials': '*******'}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,539  [#D73A]  S: SUCCESS {'server': 'Neo4j/4.4.11', 'connection_id': 'bolt-4', 'hints': {}}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,539  [#D73A]  State: CONNECTED > READY
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,539  [#D73A]  C: ROUTE {'address': 'localhost:7687'} () {'db': 'neo4j'}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,549  [#D73A]  S: SUCCESS {'rt': {'servers': [{'addresses': ['localhost:7687'], 'role': 'WRITE'}, {'addresses': ['localhost:7687'], 'role': 'READ'}, {'addresses': ['localhost:7687'], 'role': 'ROUTE'}], 'ttl': 300, 'db': 'neo4j'}}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,549  [#0000]  S: <ROUTING> table=RoutingTable(database='neo4j' routers={IPv4Address(('localhost', 7687))}, readers={IPv4Address(('localhost', 7687))}, writers={IPv4Address(('localhost', 7687))}, last_updated_time=3961.253965695, ttl=300)
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,549  [#0000]  C: <UPDATE ROUTING TABLE> address=ResolvedIPv4Address(('127.0.0.1', 7687)) (RoutingTable(database='neo4j' routers={IPv4Address(('localhost', 7687))}, readers={IPv4Address(('localhost', 7687))}, writers={IPv4Address(('localhost', 7687))}, last_updated_time=3961.253965695, ttl=300))
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,550  [#0000]  C: <ROUTING AGED> database=None
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,550  [#0000]  C: <ROUTING AGED> last_updated_time=3961.23487757 perf_time=3961.254272422
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,550  [#0000]  C: <ROUTING AGED> database=neo4j
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,550  [#0000]  C: <ROUTING AGED> last_updated_time=3961.253965695 perf_time=3961.25437554
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,550  [#0000]  C: <ACQUIRE ADDRESS> database='neo4j' address=IPv4Address(('localhost', 7687))
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,550  [#0000]  C: <RESOLVE> localhost:7687
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,550  [#0000]  C: <OPEN> 127.0.0.1:7687
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,551  [#D73C]  C: <MAGIC> 0x6060B017
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,551  [#D73C]  C: <HANDSHAKE> 0x00000005 0x00020404 0x00000104 0x00000003
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,552  [#D73C]  S: <HANDSHAKE> 0x00000404
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,552  [#D73C]  C: HELLO {'user_agent': 'neo4j-python/5.2.dev0 Python/3.7.13-final-0 (linux)', 'routing': {'address': 'localhost:7687'}, 'patch_bolt': ['utc'], 'scheme': 'basic', 'principal': 'neo4j', 'credentials': '*******'}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,554  [#D73C]  S: SUCCESS {'server': 'Neo4j/4.4.11', 'connection_id': 'bolt-5', 'hints': {}}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,554  [#D73C]  State: CONNECTED > READY
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,554  [#D73C]  C: RUN 'RETURN 1 AS n' {} {'db': 'neo4j'}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,555  [#D73C]  C: PULL {'n': 1000}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,559  [#D73C]  S: SUCCESS {'t_first': 2, 'fields': ['n']}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,559  [#D73C]  State: READY > STREAMING
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,559  [#D73C]  S: RECORD * 1
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,559  [#D73C]  S: SUCCESS {'bookmark': 'FB:kcwQyZhOaL2BSyWaQWC1sqN3EQOQ', 'type': 'r', 't_last': 1, 'db': 'neo4j'}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,559  [#D73C]  State: STREAMING > READY

[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,560  [#0000]  C: <ROUTING TABLE ENSURE FRESH> {None: RoutingTable(database=None routers={IPv4Address(('localhost', 7687))}, readers={}, writers={}, last_updated_time=3961.23487757, ttl=0), 'neo4j': RoutingTable(database='neo4j' routers={IPv4Address(('localhost', 7687))}, readers={IPv4Address(('localhost', 7687))}, writers={IPv4Address(('localhost', 7687))}, last_updated_time=3961.253965695, ttl=300)}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,560  [#0000]  C: <ROUTING> Checking table freshness (readonly=False)
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,560  [#0000]  C: <ROUTING> Table expired=False
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,560  [#0000]  C: <ROUTING> Table routers={IPv4Address(('localhost', 7687))}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,560  [#0000]  C: <ROUTING> Table has_server_for_mode=True
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,560  [#0000]  C: <ACQUIRE ADDRESS> database='neo4j' address=IPv4Address(('localhost', 7687))
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,560  [#D73C]  C: RUN 'RETURN 1 AS n' {} {'db': 'neo4j'}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,560  [#D73C]  C: PULL {'n': 1000}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,565  [#D73C]  S: SUCCESS {'t_first': 2, 'fields': ['n']}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,566  [#D73C]  State: READY > STREAMING
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,566  [#D73C]  S: RECORD * 1
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,566  [#D73C]  S: SUCCESS {'bookmark': 'FB:kcwQyZhOaL2BSyWaQWC1sqN3EQOQ', 'type': 'r', 't_last': 1, 'db': 'neo4j'}
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,566  [#D73C]  State: STREAMING > READY
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,566  [#0000]  C: <POOL> close
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,566  [#D73A]  C: GOODBYE
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,566  [#D73A]  C: <CLOSE>
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,566  [#D73C]  C: GOODBYE
[DEBUG   ] MainThread(140035918219072) 2022-11-02 09:46:04,566  [#D73C]  C: <CLOSE>

This is what the same code logs now:

[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,919  [#0000]  _: <POOL> created, routing address IPv4Address(('localhost', 7687))
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,919  [#0000]  _: <POOL> acquire routing connection
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,919  [#0000]  _: <POOL> routing table ensure fresh {None: RoutingTable(database=None routers={IPv4Address(('localhost', 7687))}, readers={}, writers={}, last_updated_time=4282.623778156, ttl=0)}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,919  [#0000]  _: <ROUTING> checking table freshness (readonly=False): table expired=True, has_server_for_mode=False, table routers={IPv4Address(('localhost', 7687))} => False
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,920  [#0000]  _: <POOL> attempting to update routing table from IPv4Address(('localhost', 7687))
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,920  [#0000]  _: <RESOLVE> in: localhost:7687
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,922  [#0000]  _: <RESOLVE> dns resolver out: 127.0.0.1:7687
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,923  [#0000]  _: <POOL> trying to hand out new connection
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,923  [#0000]  C: <OPEN> 127.0.0.1:7687
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,925  [#8C12]  C: <MAGIC> 0x6060B017
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,925  [#8C12]  C: <HANDSHAKE> 0x00000005 0x00020404 0x00000104 0x00000003
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,926  [#8C12]  S: <HANDSHAKE> 0x00000404
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,926  [#8C12]  C: HELLO {'user_agent': 'neo4j-python/5.2.dev0 Python/3.7.13-final-0 (linux)', 'routing': {'address': 'localhost:7687'}, 'patch_bolt': ['utc'], 'scheme': 'basic', 'principal': 'neo4j', 'credentials': '*******'}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,928  [#8C12]  S: SUCCESS {'server': 'Neo4j/4.4.11', 'connection_id': 'bolt-12', 'hints': {}}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,928  [#8C12]  _: <CONNECTION> state: CONNECTED > READY
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,928  [#8C12]  C: ROUTE {'address': 'localhost:7687'} () {'db': 'neo4j'}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,936  [#8C12]  S: SUCCESS {'rt': {'servers': [{'addresses': ['localhost:7687'], 'role': 'WRITE'}, {'addresses': ['localhost:7687'], 'role': 'READ'}, {'addresses': ['localhost:7687'], 'role': 'ROUTE'}], 'ttl': 300, 'db': 'neo4j'}}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,936  [#8C12]  _: <POOL> released bolt-12
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,936  [#0000]  _: <ROUTING> updated table=RoutingTable(database='neo4j' routers={IPv4Address(('localhost', 7687))}, readers={IPv4Address(('localhost', 7687))}, writers={IPv4Address(('localhost', 7687))}, last_updated_time=4282.640483177, ttl=300)
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,936  [#0000]  _: <POOL> update routing table from address=ResolvedIPv4Address(('127.0.0.1', 7687)) (RoutingTable(database='neo4j' routers={IPv4Address(('localhost', 7687))}, readers={IPv4Address(('localhost', 7687))}, writers={IPv4Address(('localhost', 7687))}, last_updated_time=4282.640483177, ttl=300))
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,936  [#0000]  _: <POOL> routing aged, database=None
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,936  [#0000]  _: <ROUTING> purge check: last_updated_time=4282.623778156, ttl=0, perf_time=4282.640782713 => False
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,936  [#0000]  _: <POOL> routing aged, database=neo4j
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,936  [#0000]  _: <ROUTING> purge check: last_updated_time=4282.640483177, ttl=300, perf_time=4282.640888854 => False
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,936  [#0000]  _: <POOL> acquire address, database='neo4j' address=IPv4Address(('localhost', 7687))
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,936  [#0000]  _: <POOL> trying to hand out new connection
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,936  [#0000]  _: <RESOLVE> in: localhost:7687
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,937  [#0000]  _: <RESOLVE> dns resolver out: 127.0.0.1:7687
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,937  [#0000]  C: <OPEN> 127.0.0.1:7687
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,937  [#8C16]  C: <MAGIC> 0x6060B017
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,937  [#8C16]  C: <HANDSHAKE> 0x00000005 0x00020404 0x00000104 0x00000003
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,938  [#8C16]  S: <HANDSHAKE> 0x00000404
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,938  [#8C16]  C: HELLO {'user_agent': 'neo4j-python/5.2.dev0 Python/3.7.13-final-0 (linux)', 'routing': {'address': 'localhost:7687'}, 'patch_bolt': ['utc'], 'scheme': 'basic', 'principal': 'neo4j', 'credentials': '*******'}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,940  [#8C16]  S: SUCCESS {'server': 'Neo4j/4.4.11', 'connection_id': 'bolt-13', 'hints': {}}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,940  [#8C16]  _: <CONNECTION> state: CONNECTED > READY
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,940  [#8C16]  C: RUN 'RETURN 1 AS n' {} {'db': 'neo4j'}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,940  [#8C16]  C: PULL {'n': 1000}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,943  [#8C16]  S: SUCCESS {'t_first': 1, 'fields': ['n']}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,943  [#8C16]  _: <CONNECTION> state: READY > STREAMING
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,943  [#8C16]  S: RECORD * 1
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,943  [#8C16]  S: SUCCESS {'bookmark': 'FB:kcwQyZhOaL2BSyWaQWC1sqN3EQOQ', 'type': 'r', 't_last': 1, 'db': 'neo4j'}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,944  [#8C16]  _: <CONNECTION> state: STREAMING > READY
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,944  [#8C16]  _: <POOL> released bolt-13

[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,944  [#0000]  _: <POOL> acquire routing connection
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,944  [#0000]  _: <POOL> routing table ensure fresh {None: RoutingTable(database=None routers={IPv4Address(('localhost', 7687))}, readers={}, writers={}, last_updated_time=4282.623778156, ttl=0), 'neo4j': RoutingTable(database='neo4j' routers={IPv4Address(('localhost', 7687))}, readers={IPv4Address(('localhost', 7687))}, writers={IPv4Address(('localhost', 7687))}, last_updated_time=4282.640483177, ttl=300)}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,944  [#0000]  _: <ROUTING> checking table freshness (readonly=False): table expired=False, has_server_for_mode=True, table routers={IPv4Address(('localhost', 7687))} => True
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,944  [#0000]  _: <POOL> acquire address, database='neo4j' address=IPv4Address(('localhost', 7687))
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,944  [#8C16]  _: <POOL> handing out existing connection bolt-13
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,944  [#8C16]  C: RUN 'RETURN 1 AS n' {} {'db': 'neo4j'}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,944  [#8C16]  C: PULL {'n': 1000}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,947  [#8C16]  S: SUCCESS {'t_first': 1, 'fields': ['n']}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,947  [#8C16]  _: <CONNECTION> state: READY > STREAMING
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,947  [#8C16]  S: RECORD * 1
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,947  [#8C16]  S: SUCCESS {'bookmark': 'FB:kcwQyZhOaL2BSyWaQWC1sqN3EQOQ', 'type': 'r', 't_last': 0, 'db': 'neo4j'}
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,947  [#8C16]  _: <CONNECTION> state: STREAMING > READY
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,947  [#8C16]  _: <POOL> released bolt-13
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,947  [#0000]  _: <POOL> close
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,947  [#8C12]  C: GOODBYE
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,947  [#8C12]  C: <CLOSE>
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,948  [#8C16]  C: GOODBYE
[DEBUG   ] [Thread 139968297072448] [Task 139968235592640] 2022-11-02 09:51:25,948  [#8C16]  C: <CLOSE>