search

atlassian-labs / db-replica

Automatically chooses between database connections to read-write main or read-only replica
Apache License 2.0
10 stars 12 forks source link

None: Add logger #160

Closed wyrzyk closed 2 years ago

wyrzyk commented 2 years ago 
connection.setAutoCommit(false);
connection.createStatement().executeQuery("SELECT 1;");
final PreparedStatement preparedStatement = connection.prepareStatement("SELECT 2;");
preparedStatement.executeQuery();
preparedStatement.executeUpdate();
connection.prepareStatement("INSERT INTO foo(bar);").executeUpdate();
connection.prepareStatement("SELECT 3;").executeQuery();
connection.commit();
connection.close();

translates to:

0 = "[state=NOT_INITIALISED] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] setAutoCommit(autoCommit='false')"
1 = "[state=NOT_INITIALISED] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] ConnectionProvider#getReplicaConnection(connection=Mock for AutoCommitAwareConnection, hashCode: 1308983694)"
2 = "[state=NOT_INITIALISED] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] Initializing connection Mock for AutoCommitAwareConnection, hashCode: 1308983694"
3 = "[state=NOT_INITIALISED] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] Initializing connection setAutoCommit(false)"
4 = "[state=NOT_INITIALISED] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] Initializing runtimeParameters Mock for AutoCommitAwareConnection, hashCode: 1308983694"
5 = "[state=REPLICA] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] ReplicaConsistency#isConsistent = true"
6 = "[state=REPLICA] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] [ReplicaStatement=84ce042d-399a-4596-9300-4b01081691f9] executeQuery(sql='SELECT 1;')"
7 = "[state=REPLICA] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] ReplicaConsistency#isConsistent = true"
8 = "[state=REPLICA] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] [ReplicaPreparedStatement=74ea3d66-28a0-4d1d-aa13-d3f1a5c56650] [sql=SELECT 2;] executeQuery()"
9 = "[state=REPLICA] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] ConnectionProvider#getMainConnection(connection=Mock for AutoCommitAwareConnection, hashCode: 394640390)"
10 = "[state=REPLICA] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] Initializing connection Mock for AutoCommitAwareConnection, hashCode: 394640390"
11 = "[state=REPLICA] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] Initializing connection setAutoCommit(false)"
12 = "[state=REPLICA] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] Initializing runtimeParameters Mock for AutoCommitAwareConnection, hashCode: 394640390"
13 = "[state=MAIN] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] [connectionType=readConnection] Closing connection"
14 = "[state=MAIN] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] [connectionType=readConnection] Closing connection(Mock for AutoCommitAwareConnection, hashCode: 1308983694) close()"
15 = "[state=MAIN] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] [ReplicaPreparedStatement=74ea3d66-28a0-4d1d-aa13-d3f1a5c56650] [sql=SELECT 2;] executeUpdate()"
16 = "[state=MAIN] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] markDirty"
17 = "[state=MAIN] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] [ReplicaPreparedStatement=bcdcdf3e-ce4f-4511-a191-23961d30181f] [sql=INSERT INTO foo(bar);] executeUpdate()"
18 = "[state=MAIN] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] markDirty"
19 = "[state=MAIN] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] [ReplicaPreparedStatement=3ba3242d-105d-4bea-b11b-011a2e96bf1f] [sql=SELECT 3;] Main connection reuse"
20 = "[state=MAIN] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] [ReplicaPreparedStatement=3ba3242d-105d-4bea-b11b-011a2e96bf1f] [sql=SELECT 3;] executeQuery()"
21 = "[state=MAIN] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] ReplicaConsistency#preCommit(connection=Mock for AutoCommitAwareConnection, hashCode: 394640390)"
22 = "[state=MAIN] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] commit()"
23 = "[state=MAIN] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] ReplicaConsistency#write(connection=Mock for AutoCommitAwareConnection, hashCode: 394640390)"
24 = "[state=MAIN] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] clearDirty"
25 = "[state=MAIN] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] close()"
26 = "[state=CLOSED] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] [connectionType=writeConnection] Closing connection"
27 = "[state=CLOSED] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] [connectionType=writeConnection] Closing connection(Mock for AutoCommitAwareConnection, hashCode: 394640390) close()"
28 = "[state=CLOSED] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] [connectionType=readConnection] Closing connection"
29 = "[state=CLOSED] [DualConnection=d228ff46-8db1-4322-b717-919cd5c827bb] [connectionType=readConnection] Connection was not initialized"
wyrzyk commented 2 years ago

We experience consistency issues for some code paths and some tenants. I plan to inject the longer and dump all the logs when we detect the inconsistency.

wyrzyk commented 2 years ago

Gave a quick look, want to unblock you.

It's a draft :)

dwatl commented 2 years ago

Is logger always enabled? It seems expensive

wyrzyk commented 2 years ago

@dwatl No, it's optional.

wyrzyk commented 2 years ago

On the product side, I plan to add a size limit for the logger, enable it only for the affected endpoints/tenants and write to the real logger only when we detect the inconsistency.