cloudflare-native port of the tangled knot server
dbdrv: log one structured line per D1 round-trip
d1Conn.post is the single D1 HTTP chokepoint for exec, query, and batch operations. Emit one Debug record from that path with op, total_ms, and http_status for each client.Do round trip.
Thread an optional *slog.Logger through a driver.Connector used by OpenConfig via log.FromContext(ctx). Keep the registered-driver sql.Open path on slog.DiscardHandler so the pure-driver path and the existing 20 contract tests stay silent and dependency-light.
Add TestD1PostObservability coverage for captured debug logs, real non-2xx status, and the silent registered-driver path.
Patch category: upstreamable-core
Signed-off-by: Jer Miller <jer@solpbc.org>
Jer Miller
(May 27, 2026, 9:59 PM -0600)
73bd2129
48b86ad8
+173
-2
+4
-2
dbdrv/dbdrv.go
+4
-2
dbdrv/dbdrv.go
···
5
5
"context"
6
6
"database/sql"
7
7
"fmt"
8
+
9
+
"tangled.org/core/log"
8
10
)
9
11
10
12
type Config struct {
···
17
19
return OpenConfig(context.Background(), Config{Backend: "sqlite", Path: path}, pragmas...)
18
20
}
19
21
20
-
func OpenConfig(_ context.Context, cfg Config, pragmas ...string) (*sql.DB, error) {
22
+
func OpenConfig(ctx context.Context, cfg Config, pragmas ...string) (*sql.DB, error) {
21
23
switch cfg.Backend {
22
24
case "", "sqlite":
23
25
return sql.Open(Name, buildDSN(cfg.Path, pragmas))
···
25
27
if cfg.URL == "" {
26
28
return nil, fmt.Errorf("dbdrv: d1 backend requires non-empty URL")
27
29
}
28
-
return sql.Open("aerie-d1", cfg.URL)
30
+
return sql.OpenDB(&d1Connector{url: cfg.URL, logger: log.FromContext(ctx)}), nil
29
31
default:
30
32
return nil, fmt.Errorf("dbdrv: unknown backend %q", cfg.Backend)
31
33
}
+34
dbdrv/driver_d1.go
+34
dbdrv/driver_d1.go
···
10
10
"errors"
11
11
"fmt"
12
12
"io"
13
+
"log/slog"
13
14
"math"
14
15
"net/http"
15
16
"net/url"
···
110
111
type d1Driver struct{}
111
112
112
113
func (d *d1Driver) Open(name string) (driver.Conn, error) {
114
+
return newConn(name, slog.New(slog.DiscardHandler))
115
+
}
116
+
117
+
func newConn(name string, logger *slog.Logger) (*d1Conn, error) {
113
118
if name == "" {
114
119
return nil, fmt.Errorf("dbdrv: d1 URL is empty")
115
120
}
···
123
128
return &d1Conn{
124
129
url: strings.TrimRight(name, "/"),
125
130
client: &http.Client{Timeout: d1HTTPTimeout},
131
+
logger: logger,
126
132
}, nil
127
133
}
128
134
135
+
type d1Connector struct {
136
+
url string
137
+
logger *slog.Logger
138
+
}
139
+
140
+
func (dc *d1Connector) Connect(context.Context) (driver.Conn, error) {
141
+
logger := dc.logger
142
+
if logger == nil {
143
+
logger = slog.New(slog.DiscardHandler)
144
+
}
145
+
return newConn(dc.url, logger)
146
+
}
147
+
148
+
func (dc *d1Connector) Driver() driver.Driver {
149
+
return &d1Driver{}
150
+
}
151
+
129
152
type d1Conn struct {
130
153
mu sync.Mutex
131
154
url string
132
155
client *http.Client
156
+
logger *slog.Logger
133
157
tx *d1Tx
134
158
}
135
159
···
241
265
}
242
266
req.Header.Set("content-type", "application/json")
243
267
268
+
start := time.Now()
244
269
resp, err := c.client.Do(req)
270
+
status := 0
271
+
if resp != nil {
272
+
status = resp.StatusCode
273
+
}
274
+
c.logger.Debug("d1 round-trip",
275
+
"op", payload.Op,
276
+
"total_ms", time.Since(start).Milliseconds(),
277
+
"http_status", status,
278
+
)
245
279
if err != nil {
246
280
return &TransportError{Err: err}
247
281
}
+135
dbdrv/driver_d1_test.go
+135
dbdrv/driver_d1_test.go
···
1
1
package dbdrv
2
2
3
3
import (
4
+
"bytes"
4
5
"context"
5
6
"database/sql"
6
7
"encoding/json"
7
8
"errors"
9
+
"log/slog"
8
10
"net/http"
9
11
"net/http/httptest"
10
12
"strconv"
11
13
"strings"
12
14
"sync"
13
15
"testing"
16
+
17
+
"tangled.org/core/dbdrv/testfake"
18
+
"tangled.org/core/log"
14
19
)
15
20
16
21
func TestD1DriverContract(t *testing.T) {
···
44
49
}
45
50
for _, tt := range tests {
46
51
t.Run(tt.name, tt.run)
52
+
}
53
+
}
54
+
55
+
func TestD1PostObservability(t *testing.T) {
56
+
t.Run("success_exec_query_logs_debug", func(t *testing.T) {
57
+
fake := testfake.New(t)
58
+
var buf bytes.Buffer
59
+
ctx := captureD1Logger(&buf)
60
+
db, err := OpenConfig(ctx, Config{Backend: "d1", URL: fake.URL})
61
+
if err != nil {
62
+
t.Fatalf("open d1: %v", err)
63
+
}
64
+
t.Cleanup(func() { db.Close() })
65
+
66
+
if _, err := db.ExecContext(ctx, `CREATE TABLE observability (id integer)`); err != nil {
67
+
t.Fatalf("exec: %v", err)
68
+
}
69
+
var got int
70
+
if err := db.QueryRowContext(ctx, `SELECT 1`).Scan(&got); err != nil {
71
+
t.Fatalf("query: %v", err)
72
+
}
73
+
if got != 1 {
74
+
t.Fatalf("query result = %d, want 1", got)
75
+
}
76
+
77
+
records := readRoundTripRecords(t, &buf)
78
+
if len(records) != 2 {
79
+
t.Fatalf("log record count = %d, want 2; records=%v", len(records), records)
80
+
}
81
+
assertRoundTripRecord(t, records[0], "exec", http.StatusOK)
82
+
assertRoundTripRecord(t, records[1], "query", http.StatusOK)
83
+
})
84
+
85
+
t.Run("non_2xx_logs_real_status", func(t *testing.T) {
86
+
srv := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
87
+
w.WriteHeader(http.StatusInternalServerError)
88
+
_, _ = w.Write([]byte("boom"))
89
+
}))
90
+
t.Cleanup(srv.Close)
91
+
92
+
var buf bytes.Buffer
93
+
ctx := captureD1Logger(&buf)
94
+
db, err := OpenConfig(ctx, Config{Backend: "d1", URL: srv.URL})
95
+
if err != nil {
96
+
t.Fatalf("open d1: %v", err)
97
+
}
98
+
t.Cleanup(func() { db.Close() })
99
+
100
+
_, err = db.ExecContext(ctx, `insert one`, 1)
101
+
if err == nil {
102
+
t.Fatal("exec error = nil, want transport error")
103
+
}
104
+
var transportErr *TransportError
105
+
if !errors.As(err, &transportErr) || transportErr.Status != http.StatusInternalServerError {
106
+
t.Fatalf("exec error = %v, want status 500 TransportError", err)
107
+
}
108
+
109
+
records := readRoundTripRecords(t, &buf)
110
+
if len(records) != 1 {
111
+
t.Fatalf("log record count = %d, want 1; records=%v", len(records), records)
112
+
}
113
+
assertRoundTripRecord(t, records[0], "exec", http.StatusInternalServerError)
114
+
})
115
+
116
+
t.Run("default_path_silent", func(t *testing.T) {
117
+
fake := testfake.New(t)
118
+
var buf bytes.Buffer
119
+
prev := slog.Default()
120
+
defer slog.SetDefault(prev)
121
+
slog.SetDefault(slog.New(slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelDebug})))
122
+
123
+
db, err := sql.Open(d1DriverName, fake.URL)
124
+
if err != nil {
125
+
t.Fatalf("open: %v", err)
126
+
}
127
+
t.Cleanup(func() { db.Close() })
128
+
129
+
if _, err := db.Exec(`CREATE TABLE silent (id integer)`); err != nil {
130
+
t.Fatalf("exec: %v", err)
131
+
}
132
+
if buf.Len() != 0 {
133
+
t.Fatalf("registered driver emitted logs through slog default: %q", buf.String())
134
+
}
135
+
})
136
+
}
137
+
138
+
func captureD1Logger(buf *bytes.Buffer) context.Context {
139
+
capLogger := slog.New(slog.NewJSONHandler(buf, &slog.HandlerOptions{Level: slog.LevelDebug}))
140
+
return log.IntoContext(context.Background(), capLogger)
141
+
}
142
+
143
+
func readRoundTripRecords(t *testing.T, buf *bytes.Buffer) []map[string]any {
144
+
t.Helper()
145
+
text := strings.TrimSpace(buf.String())
146
+
if text == "" {
147
+
return nil
148
+
}
149
+
lines := strings.Split(text, "\n")
150
+
records := make([]map[string]any, 0, len(lines))
151
+
for _, line := range lines {
152
+
var record map[string]any
153
+
if err := json.Unmarshal([]byte(line), &record); err != nil {
154
+
t.Fatalf("decode log record %q: %v", line, err)
155
+
}
156
+
records = append(records, record)
157
+
}
158
+
return records
159
+
}
160
+
161
+
func assertRoundTripRecord(t *testing.T, record map[string]any, op string, status int) {
162
+
t.Helper()
163
+
if got, _ := record["msg"].(string); got != "d1 round-trip" {
164
+
t.Fatalf("msg = %v, want d1 round-trip; record=%v", record["msg"], record)
165
+
}
166
+
if got, _ := record["op"].(string); got != op {
167
+
t.Fatalf("op = %v, want %s; record=%v", record["op"], op, record)
168
+
}
169
+
totalMS, ok := record["total_ms"].(float64)
170
+
if !ok {
171
+
t.Fatalf("total_ms = %T(%v), want number; record=%v", record["total_ms"], record["total_ms"], record)
172
+
}
173
+
if totalMS < 0 {
174
+
t.Fatalf("total_ms = %v, want >= 0; record=%v", totalMS, record)
175
+
}
176
+
httpStatus, ok := record["http_status"].(float64)
177
+
if !ok {
178
+
t.Fatalf("http_status = %T(%v), want number; record=%v", record["http_status"], record["http_status"], record)
179
+
}
180
+
if httpStatus != float64(status) {
181
+
t.Fatalf("http_status = %v, want %d; record=%v", httpStatus, status, record)
47
182
}
48
183
}
49
184