Data races in `log/log_broker_hook.go`

[Mazen050]

Describe the bug

Running the webserver tests with the race detector exposes three data races in internal/log/log_broker_hook.go.

Two data races occur because BrokerHook.send() reads hook.subscribers before holding the mutex, while AddSubscriber() and RemoveSubscriber() modify the same hook.subscribers under the mutex, allowing concurrent read/write access that may result in inconsistent subscriber lists or lost log messages.

The third race occurs because a *logrus.Entry is processed asynchronously. The formatter may read the Entry while Logrus is still mutating it, resulting in concurrent read/write access to the Entry fields.

To Reproduce
Steps to reproduce the behavior:

1. Create a minimal file-based sources configuration:

cd pgwatch
mkdir -p repro

cat <<EOF > repro/sources.yaml
- name: db1
  kind: postgres
  conn_str: "postgres://postgres@localhost/postgres"
EOF

2. build and run with race detector:

docker run -it --rm   -v $(pwd):/pgwatch   -w /pgwatch   golang:1.26   bash -c "go run -race ./cmd/pgwatch \
    --sources /pgwatch/repro/sources.yaml \
    --sink prometheus://0.0.0.0:9187"

3. get token from /login:

curl -s -X POST http://localhost:8080/login \
  -H "Content-Type: application/json" \
  -d '{"username":"","password":""}'

4. in a new terminal simulate connecting to logs websocket (after getting token from /login):

websocat ws://localhost:8080/log?Token={token}

5. go to first terminal and see data race warning (first race immediately appears wait two minutes for the 2nd race)
6. disconnect the websocet and wait two minutes for third data race (removesubscriber):

Output:

**Click to expand**

2026-03-07 19:26:12.824 [INFO] [sink:prometheus] [address:0.0.0.0:9187] measurements sink is activated
2026-03-07 19:26:12.824 [INFO] [sources:0] sources refreshed
2026-03-07 19:26:12.878 [INFO] [metrics:74] [presets:14] metrics and presets refreshed
==================
WARNING: DATA RACE
Write at 0x00c00060a7e8 by goroutine 44:
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.(*BrokerHook).AddSubscriber()
      /pgwatch/internal/log/log_broker_hook.go:52 +0x19a
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.writer()
      /pgwatch/internal/webserver/wslog.go:53 +0x125
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.writer()
      /pgwatch/internal/webserver/wslog.go:53 +0x125
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.(*WebUIServer).serveWsLog.gowrap1()
      /pgwatch/internal/webserver/wslog.go:83 +0x54

Previous read at 0x00c00060a7e8 by goroutine 35:
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.(*BrokerHook).send()
      /pgwatch/internal/log/log_broker_hook.go:135 +0x51
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.(*BrokerHook).poll()
      /pgwatch/internal/log/log_broker_hook.go:128 +0x44
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.NewBrokerHook.gowrap1()
      /pgwatch/internal/log/log_broker_hook.go:44 +0x38

Goroutine 44 (running) created at:
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.(*WebUIServer).serveWsLog()
      /pgwatch/internal/webserver/wslog.go:83 +0x35c
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.(*WebUIServer).serveWsLog()
      /pgwatch/internal/webserver/wslog.go:80 +0x103
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.(*WebUIServer).serveWsLog-fm()
      <autogenerated>:1 +0x48
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.(*EnsureAuth).ServeHTTP()
      /pgwatch/internal/webserver/jwt.go:66 +0x9a
  net/http.(*ServeMux).ServeHTTP()
      /usr/local/go/src/net/http/server.go:2828 +0x242
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.Init.corsMiddleware.func2()
      /pgwatch/internal/webserver/webserver.go:220 +0x241
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2286 +0x47
  net/http.serverHandler.ServeHTTP()
      /usr/local/go/src/net/http/server.go:3311 +0x2a1
  net/http.(*conn).serve()
      /usr/local/go/src/net/http/server.go:2073 +0xda4
  net/http.(*Server).Serve.gowrap3()
      /usr/local/go/src/net/http/server.go:3464 +0x46

Goroutine 35 (running) created at:
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.NewBrokerHook()
      /pgwatch/internal/log/log_broker_hook.go:44 +0x33c
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.Init()
      /pgwatch/internal/log/log.go:59 +0x230
  main.main()
      /pgwatch/cmd/pgwatch/main.go:74 +0x42a
==================
2026-03-07 19:28:07.757 [INFO] [sources:0] sources refreshed
==================
WARNING: DATA RACE
Read at 0x00c00019a278 by goroutine 35:
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.(*Formatter).writeCaller()
      /pgwatch/internal/log/formatter.go:152 +0x58
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.(*Formatter).Format()
      /pgwatch/internal/log/formatter.go:134 +0x5f6
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.(*BrokerHook).send()
      /pgwatch/internal/log/log_broker_hook.go:140 +0x13c
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.(*BrokerHook).poll()
      /pgwatch/internal/log/log_broker_hook.go:128 +0x44
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.NewBrokerHook.gowrap1()
      /pgwatch/internal/log/log_broker_hook.go:44 +0x38

Previous write at 0x00c00019a278 by main goroutine:
  github.com/sirupsen/logrus.(*Entry).log()
      /go/pkg/mod/github.com/sirupsen/logrus@v1.9.4/entry.go:257 +0x9b1
  github.com/sirupsen/logrus.(*Entry).Log()
      /go/pkg/mod/github.com/sirupsen/logrus@v1.9.4/entry.go:307 +0x8b
  github.com/sirupsen/logrus.(*Entry).Info()
      /go/pkg/mod/github.com/sirupsen/logrus@v1.9.4/entry.go:324 +0xb8e
  github.com/cybertec-postgresql/pgwatch/v5/internal/reaper.(*Reaper).LoadSources()
      /pgwatch/internal/reaper/reaper.go:430 +0xab9
  github.com/cybertec-postgresql/pgwatch/v5/internal/reaper.(*Reaper).LoadSources()
      /pgwatch/internal/reaper/reaper.go:430 +0xb30
  github.com/cybertec-postgresql/pgwatch/v5/internal/reaper.(*Reaper).Reap()
      /pgwatch/internal/reaper/reaper.go:90 +0x414
  github.com/cybertec-postgresql/pgwatch/v5/internal/reaper.(*Reaper).Reap()
      /pgwatch/internal/reaper/reaper.go:93 +0x4a4
  github.com/cybertec-postgresql/pgwatch/v5/internal/reaper.(*Reaper).Reap()
      /pgwatch/internal/reaper/reaper.go:90 +0x414
  main.main()
      /pgwatch/cmd/pgwatch/main.go:113 +0xe19
  main.main()
      /pgwatch/cmd/pgwatch/main.go:85 +0x866

Goroutine 35 (running) created at:
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.NewBrokerHook()
      /pgwatch/internal/log/log_broker_hook.go:44 +0x33c
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.Init()
      /pgwatch/internal/log/log.go:59 +0x230
  main.main()
      /pgwatch/cmd/pgwatch/main.go:74 +0x42a
==================
2026-03-07 19:33:52.494 [INFO] [sources:0] sources refreshed
==================
WARNING: DATA RACE
Read at 0x00c00060a7e8 by goroutine 35:
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.(*BrokerHook).send()
      /pgwatch/internal/log/log_broker_hook.go:135 +0x51
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.(*BrokerHook).poll()
      /pgwatch/internal/log/log_broker_hook.go:128 +0x44
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.NewBrokerHook.gowrap1()
      /pgwatch/internal/log/log_broker_hook.go:44 +0x38

Previous write at 0x00c00060a7e8 by goroutine 44:
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.(*BrokerHook).RemoveSubscriber()
      /pgwatch/internal/log/log_broker_hook.go:59 +0x16d
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.writer.deferwrap1()
      /pgwatch/internal/webserver/wslog.go:54 +0x4a
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.writer.deferwrap1()
      /pgwatch/internal/webserver/wslog.go:54 +0x4a
  runtime.deferreturn()
      /usr/local/go/src/runtime/panic.go:668 +0x5d
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.writer()
      /pgwatch/internal/webserver/wslog.go:53 +0x125
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.(*WebUIServer).serveWsLog.gowrap1()
      /pgwatch/internal/webserver/wslog.go:83 +0x54

Goroutine 35 (running) created at:
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.NewBrokerHook()
      /pgwatch/internal/log/log_broker_hook.go:44 +0x33c
  github.com/cybertec-postgresql/pgwatch/v5/internal/log.Init()
      /pgwatch/internal/log/log.go:59 +0x230
  main.main()
      /pgwatch/cmd/pgwatch/main.go:74 +0x42a

Goroutine 44 (finished) created at:
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.(*WebUIServer).serveWsLog()
      /pgwatch/internal/webserver/wslog.go:83 +0x35c
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.(*WebUIServer).serveWsLog()
      /pgwatch/internal/webserver/wslog.go:80 +0x103
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.(*WebUIServer).serveWsLog-fm()
      <autogenerated>:1 +0x48
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.(*EnsureAuth).ServeHTTP()
      /pgwatch/internal/webserver/jwt.go:66 +0x9a
  net/http.(*ServeMux).ServeHTTP()
      /usr/local/go/src/net/http/server.go:2828 +0x242
  github.com/cybertec-postgresql/pgwatch/v5/internal/webserver.Init.corsMiddleware.func2()
      /pgwatch/internal/webserver/webserver.go:220 +0x241
  net/http.HandlerFunc.ServeHTTP()
      /usr/local/go/src/net/http/server.go:2286 +0x47
  net/http.serverHandler.ServeHTTP()
      /usr/local/go/src/net/http/server.go:3311 +0x2a1
  net/http.(*conn).serve()
      /usr/local/go/src/net/http/server.go:2073 +0xda4
  net/http.(*Server).Serve.gowrap3()
      /usr/local/go/src/net/http/server.go:3464 +0x46
==================
2026-03-07 19:33:52.549 [INFO] [metrics:74] [presets:14] metrics and presets refreshed

Expected behavior
expected no race warnings to happen from race detector.

Note: please note that I have fixed them and the fix is minimal so thats why I didn't open multiple issues.

[Mazen050]

I have PR ready to send after triage

[0xgouda]

For the millionth time, we need a clear reprduction steps that convinces us that this is an actual bug.

the thing might be designed to be called by one routine or multiple other reasons, and me trying to reproduce it wastes my time.

at least seeing how hard the reproduce might be this will adjust the issue priority.

please stop using ai to blindly scan for issues and then send them without even spending a little time trying to reproduce.

otherwise i am sorry, i wont review.

[pashagolub]

what is the fix?

[Mazen050]

@pashagolub Hello, for the addsubscriber and removesubscriber races its simple. The problem is that the send() function has a lock but it accesses subscribers before the lock. just moving the lock to be before the call to access subscribers fixes the two races.

now for the entry race the problem is that the entry can be accessed at the same time so making a copy in fire() would fix this. I have tried using entry.Dup but dup doesn't copy important needed attributes like entry.caller and entry.Message I tried making a manual copy which works but is a bit static if new attributes are added and it can't copy entry.err because its unexported. So I opted for an in between fix with using .Dup and adding other needed attributes (like caller and message).

I added my thought process since you sometimes ask for it I hope its not too long. I will send a PR so that its better to check the code to understand more.