Watermill

Troubleshooting

Logging

In most cases, you will find the answer to your problem in the logs. Watermill offers a significant amount of logs on different severity levels.

If you are using StdLoggerAdapter, just change debug, and trace options to true:

logger := watermill.NewStdLogger(true, true)

Debugging Pub/Sub tests

Running a single test

make up
go test -v ./... -run TestPublishSubscribe/TestContinueAfterSubscribeClose

grep is your friend

Each executed test case has a unique UUID. It’s used in the topic’s name. Thanks to that, you can easily grep the output of the test. It gives you detailed information about the test execution.

> go test -v ./... > test.out

> less test.out

// ...

--- PASS: TestPublishSubscribe (0.00s)
    --- PASS: TestPublishSubscribe/TestPublishSubscribe (2.38s)
        --- PASS: TestPublishSubscribe/TestPublishSubscribe/81eeb56c-3336-4eb9-a0ac-13abda6f38ff (2.38s)
cat test.out | grep 81eeb56c-3336-4eb9-a0ac-13abda6f38ff | less

[watermill] 2020/08/18 14:51:46.283366 subscriber.go:300:       level=TRACE msg="Msg acked" message_uuid=5c920330-5075-4870-8d86-9013771eee78 provider=google_cloud_pubsub subscription_name=topic_81eeb56c-3336-4eb9-a0ac-13abda6f38ff topic=topic_81eeb56c-3336-4eb9-a0ac-13abda6f38ff
[watermill] 2020/08/18 14:51:46.283405 subscriber.go:300:       level=TRACE msg="Msg acked" message_uuid=46e04a08-994e-4c04-afff-7fd42fd67f95 provider=google_cloud_pubsub subscription_name=topic_81eeb56c-3336-4eb9-a0ac-13abda6f38ff topic=topic_81eeb56c-3336-4eb9-a0ac-13abda6f38ff
2020/08/18 14:51:46 all messages (100/100) received in bulk read after 110.04155ms of 45s (test ID: 81eeb56c-3336-4eb9-a0ac-13abda6f38ff)
[watermill] 2020/08/18 14:51:46.284569 subscriber.go:186:       level=DEBUG msg="Closing message consumer" provider=google_cloud_pubsub subscription_name=topic_81eeb56c-3336-4eb9-a0ac-13abda6f38ff topic=topic_81eeb56c-3336-4eb9-a0ac-13abda6f38ff
[watermill] 2020/08/18 14:51:46.284828 subscriber.go:300:       level=TRACE msg="Msg acked" message_uuid=2f409208-d4d2-46f6-b6b9-afb1aea0e59f provider=google_cloud_pubsub subscription_name=topic_81eeb56c-3336-4eb9-a0ac-13abda6f38ff topic=topic_81eeb56c-3336-4eb9-a0ac-13abda6f38ff
        --- PASS: TestPublishSubscribe/TestPublishSubscribe/81eeb56c-3336-4eb9-a0ac-13abda6f38ff (2.38s)

I have a deadlock

When running locally, you can send a SIGQUIT to the running process:

  • CTRL + \ on Linux
  • kill -s SIGQUIT [pid] on other UNIX systems

This will kill the process and print all goroutines along with lines on which they have stopped.

SIGQUIT: quit
PC=0x45e7c3 m=0 sigcode=128

goroutine 1 [runnable]:
github.com/ThreeDotsLabs/watermill/pubsub/gochannel.(*GoChannel).sendMessage(0xc000024100, 0x7c5250, 0xd, 0xc000872d70, 0x0, 0x0)
	/home/example/go/src/github.com/ThreeDotsLabs/watermill/pubsub/gochannel/pubsub.go:83 +0x36a
github.com/ThreeDotsLabs/watermill/pubsub/gochannel.(*GoChannel).Publish(0xc000024100, 0x7c5250, 0xd, 0xc000098530, 0x1, 0x1, 0x0, 0x0)
	/home/example/go/src/github.com/ThreeDotsLabs/watermill/pubsub/gochannel/pubsub.go:53 +0x6d
main.publishMessages(0x7fdf7a317000, 0xc000024100)
	/home/example/go/src/github.com/ThreeDotsLabs/watermill/docs/src-link/_examples/pubsubs/go-channel/main.go:43 +0x1ec
main.main()
	/home/example/go/src/github.com/ThreeDotsLabs/watermill/docs/src-link/_examples/pubsubs/go-channel/main.go:36 +0x20a

// ...

When running in production and you don’t want to kill the entire process, a better idea is to use pprof .

You can visit http://localhost:6060/debug/pprof/goroutine?debug=1 on your local machine to see all goroutines status.

goroutine profile: total 5
1 @ 0x41024c 0x6a8311 0x6a9bcb 0x6a948d 0x7028bc 0x70260a 0x42f187 0x45c971
#	0x6a8310	github.com/ThreeDotsLabs/watermill.LogFields.Add+0xd0							/home/example/go/src/github.com/ThreeDotsLabs/watermill/log.go:15
#	0x6a9bca	github.com/ThreeDotsLabs/watermill/pubsub/gochannel.(*GoChannel).sendMessage+0x6fa	/home/example/go/src/github.com/ThreeDotsLabs/watermill/pubsub/gochannel/pubsub.go:75
#	0x6a948c	github.com/ThreeDotsLabs/watermill/pubsub/gochannel.(*GoChannel).Publish+0x6c		/home/example/go/src/github.com/ThreeDotsLabs/watermill/pubsub/gochannel/pubsub.go:53
#	0x7028bb	main.publishMessages+0x1eb										/home/example/go/src/github.com/ThreeDotsLabs/watermill/docs/src-link/_examples/pubsubs/go-channel/main.go:43
#	0x702609	main.main+0x209												/home/example/go/src/github.com/ThreeDotsLabs/watermill/docs/src-link/_examples/pubsubs/go-channel/main.go:36
#	0x42f186	runtime.main+0x206											/usr/lib/go/src/runtime/proc.go:201

// ...
Help us improve this page
Prev
CQRS Component
Next
Articles

Check our online hands-on training