cockroachdb / cockroachdb/cockroach

logging: improve on PGSQL protocol level messaging

Open
#99,135 2 comments 0 reactions 0 assignees View on GitHub
A-logging A-sql-pgwire C-enhancement
Dominant language
Go
Stars
32.5k
Forks
4.1k
PR merge metrics
PR metrics pending

Description

I successfully pulled the logs by calling `http://localhost:8080/debug/logspy?count=10000&duration=10s&grep=.&flatten=1&vmodule=*=2` .

The stmt is executed by this code; it uses psycopg 3.

```python
import psycopg
import time

dburl = "postgres://root@crlMBP-C02D64WKMD6TMjg5.local:26257/defaultdb?sslmode=disable"

with psycopg.connect(dburl, autocommit=True) as conn:
time.sleep(2)
with conn.cursor() as cur0:
cur0.execute("""delete from t where id = any (%s, %s)""", (155, 233), prepare=True)
time.sleep(2)
```

I purposely sleep between conn creation, stmt exec and termination to identify them later in the log, nicely spaced 2s apart. Note: it's a prepared stmt; it's auto-committed.

In wireshark, the message flow is very clear once I filter for PGSQL (omitted the conn creation messages):

```text
No. Time Source Destination SrcPort Protocol Len Info
131 7.416057 192.168.0.115 192.168.0.115 51145 PGSQL 121 >P/S
133 7.417079 192.168.0.115 192.168.0.115 26257 PGSQL 67 <1/Z
135 7.417286 192.168.0.115 192.168.0.115 51145 PGSQL 115 >B/D/E/S
137 7.418998 192.168.0.115 192.168.0.115 26257 PGSQL 86 <2/n/C/Z
151 9.422345 192.168.0.115 192.168.0.115 51145 PGSQL 61 >X
```

In the logs, I see when the connection is created

```
I230321 14:57:34.399684 115192 sql/pgwire/conn.go:164 ⋮ [n1,client=192.168.0.115:51023] 20575 new connection with options: {User:‹root› IsSuperuser:true SessionDefaults:map[‹database›:‹defaultdb›] CustomOptionSessionDefaults:map[] RemoteAddr:‹192.168.0.115:51023› ConnResultsBufferSize:16384 SessionRevivalToken:[] JWTAuthEnabled:false}
```

I see the inbound Parse/Sync

```
I230321 14:57:36.401754 115192 sql/pgwire/conn.go:440 ⋮ [n1,client=192.168.0.115:51023,user=root] 20660 pgwire: processing ‹ClientMsgParse›
I230321 14:57:36.402030 115192 sql/pgwire/conn.go:440 ⋮ [n1,client=192.168.0.115:51023,user=root] 20661 pgwire: processing ‹ClientMsgSync›
```

But don't see the outbound `1/Z` that is, the **ParseCompletion** and **ReadyForQuery**.

Similarly, I see the `B/D/E/S`

```
I230321 14:57:36.403292 115192 sql/pgwire/conn.go:440 ⋮ [n1,client=192.168.0.115:51023,user=root] 20687 pgwire: processing ‹ClientMsgBind›
I230321 14:57:36.403352 115192 sql/pgwire/conn.go:440 ⋮ [n1,client=192.168.0.115:51023,user=root] 20688 pgwire: processing ‹ClientMsgDescribe›
I230321 14:57:36.403372 115192 sql/pgwire/conn.go:440 ⋮ [n1,client=192.168.0.115:51023,user=root] 20689 pgwire: processing ‹ClientMsgExecute›
I230321 14:57:36.403388 115192 sql/pgwire/conn.go:440 ⋮ [n1,client=192.168.0.115:51023,user=root] 20690 pgwire: processing ‹ClientMsgSync›
```

but don't see the outbound `2/n/C/Z` i.e. **BindCompletion, No-data, CommandCompletion, ReadyForQuery**.

Upon inspecting the code - within my limited understanding of Go - I see that we print out incoming messages https://github.com/cockroachdb/cockroach/blob/v22.2.2/pkg/sql/pgwire/conn.go#L440 (i'm using v22.2.2 locally..) but for example don't see the same line of code for the [ReadyForQuery](https://github.com/cockroachdb/cockroach/blob/v22.2.2/pkg/sql/pgwire/conn.go#L796) or [CommandComplete](https://github.com/cockroachdb/cockroach/blob/v22.2.2/pkg/sql/pgwire/conn.go#L1214) .

[slack](https://cockroachlabs.slack.com/archives/CHVV403F0/p1679331893916069)

Jira issue: CRDB-25718

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.