Skip to content

[3.x] Better logging around connection creation/closing #239

Open
@avelanarius

Description

@avelanarius

When debugging connection issues, the current logging is insufficient. An example snippet of logs from a real-world connection issue:

2023-07-26 20:50:48,073:[DEBUG]:[com.datastax.driver.core.Connection]:[cluster1-nio-worker-0]:[Connection[/XXX.XXX.XXX.XXX:9042-25729, inFlight=0, closed=false] Connection established, initializing transport]
2023-07-26 20:50:48,073:[DEBUG]:[com.datastax.driver.core.Connection]:[cluster1-nio-worker-0]:[Connection[/XXX.XXX.XXX.XXX:9042-25727, inFlight=0, closed=false] Connection established, initializing transport]
2023-07-26 20:50:48,073:[DEBUG]:[com.datastax.driver.core.Connection]:[cluster1-nio-worker-1]:[Connection[/XXX.XXX.XXX.XXX:9042-25728, inFlight=0, closed=false] Connection established, initializing transport]
2023-07-26 20:50:48,074:[DEBUG]:[com.datastax.driver.core.Connection]:[cluster1-nio-worker-0]:[Connection[/YYY.YYY.YYY.YYY:9042-8033, inFlight=0, closed=true] closing connection]
2023-07-26 20:50:48,074:[DEBUG]:[com.datastax.driver.core.Host.STATES]:[cluster1-nio-worker-0]:[[/YYY.YYY.YYY.YYY:9042] Connection[/YYY.YYY.YYY.YYY:9042-8033, inFlight=0, closed=true] closed, remaining = 42]
2023-07-26 20:50:48,074:[DEBUG]:[com.datastax.driver.core.Host.STATES]:[cluster1-nio-worker-0]:[[/YYY.YYY.YYY.YYY:9042] preparing to open 1 new connections, total = 43]
2023-07-26 20:50:48,075:[DEBUG]:[com.datastax.driver.core.Connection]:[cluster1-nio-worker-1]:[Connection[/YYY.YYY.YYY.YYY:9042-8062, inFlight=0, closed=false] Connection established, initializing transport]
2023-07-26 20:50:48,080:[DEBUG]:[com.datastax.driver.core.Host.STATES]:[cluster1-nio-worker-0]:[[/XXX.XXX.XXX.XXX:9042] Connection[/XXX.XXX.XXX.XXX:9042-25727, inFlight=0, closed=false] Transport initialized, connection ready]
2023-07-26 20:50:48,084:[DEBUG]:[com.datastax.driver.core.Host.STATES]:[cluster1-nio-worker-0]:[[/XXX.XXX.XXX.XXX:9042] Connection[/XXX.XXX.XXX.XXX:9042-25729, inFlight=0, closed=false] Transport initialized, connection ready]
2023-07-26 20:50:48,086:[DEBUG]:[com.datastax.driver.core.Host.STATES]:[cluster1-nio-worker-1]:[[/YYY.YYY.YYY.YYY:9042] Connection[/YYY.YYY.YYY.YYY:9042-8062, inFlight=0, closed=false] Transport initialized, connection ready]
2023-07-26 20:50:48,086:[DEBUG]:[com.datastax.driver.core.Host.STATES]:[cluster1-nio-worker-1]:[[/XXX.XXX.XXX.XXX:9042] Connection[/XXX.XXX.XXX.XXX:9042-25728, inFlight=0, closed=false] Transport initialized, connection ready]
2023-07-26 20:50:48,086:[DEBUG]:[com.datastax.driver.core.Connection]:[cluster1-nio-worker-1]:[Connection[/XXX.XXX.XXX.XXX:9042-25699, inFlight=0, closed=true] closing connection]
2023-07-26 20:50:48,086:[DEBUG]:[com.datastax.driver.core.Host.STATES]:[cluster1-nio-worker-1]:[[/XXX.XXX.XXX.XXX:9042] Connection[/XXX.XXX.XXX.XXX:9042-25699, inFlight=0, closed=true] closed, remaining = 41]
2023-07-26 20:50:48,086:[DEBUG]:[com.datastax.driver.core.Connection]:[cluster1-nio-worker-1]:[Connection[/XXX.XXX.XXX.XXX:9042-25700, inFlight=0, closed=true] closing connection]
2023-07-26 20:50:48,086:[DEBUG]:[com.datastax.driver.core.Host.STATES]:[cluster1-nio-worker-1]:[[/XXX.XXX.XXX.XXX:9042] Connection[/XXX.XXX.XXX.XXX:9042-25700, inFlight=0, closed=true] closed, remaining = 40]
2023-07-26 20:50:48,086:[DEBUG]:[com.datastax.driver.core.Connection]:[cluster1-nio-worker-1]:[Connection[/XXX.XXX.XXX.XXX:9042-25701, inFlight=0, closed=true] closing connection]
2023-07-26 20:50:48,086:[DEBUG]:[com.datastax.driver.core.Host.STATES]:[cluster1-nio-worker-1]:[[/XXX.XXX.XXX.XXX:9042] Connection[/XXX.XXX.XXX.XXX:9042-25701, inFlight=0, closed=true] closed, remaining = 39]
2023-07-26 20:50:48,086:[DEBUG]:[com.datastax.driver.core.Host.STATES]:[cluster1-nio-worker-1]:[[/XXX.XXX.XXX.XXX:9042] preparing to open 3 new connections, total = 42]
2023-07-26 20:50:48,087:[DEBUG]:[com.datastax.driver.core.Connection]:[cluster1-nio-worker-0]:[Connection[/XXX.XXX.XXX.XXX:9042-25730, inFlight=0, closed=false] Connection established, initializing transport]
2023-07-26 20:50:48,087:[DEBUG]:[com.datastax.driver.core.Connection]:[cluster1-nio-worker-1]:[Connection[/XXX.XXX.XXX.XXX:9042-25731, inFlight=0, closed=false] Connection established, initializing transport]

The logs are missing the reason for closing the connection making it hard to determine the root cause.

Metadata

Metadata

Assignees

Labels

enhancementNew feature or request

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions