Cryptic stack trace from panic during message handling.

[jmalloc]

If a handler panics while handling a message the stack trace and test output can be quite cryptic. I think this is because of testkit's panic handler which attempts to add additional information to the dogma.UnexpectedMessage panic value.

Because it recovers to test for this particular panic value, information about any OTHER kind of panic value is lost. We may have to move this "panic wrangling" out of the engine and into the test itself so it can be caught at the highest level and provide context at that point. These are panics for a reason, I don't really want the engine itself to suppress them.

Here's an example provided by @koden-km, which occurred when a panic occurred due to an invalid message.

~/grit/github.com/dogmatiq/example │   validation !12 ────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────── 11:16:14 
❯ make
go test ./...
?   	github.com/dogmatiq/example	[no test files]
?   	github.com/dogmatiq/example/cmd/bank	[no test files]
?   	github.com/dogmatiq/example/cmd/graph	[no test files]
?   	github.com/dogmatiq/example/database	[no test files]
--- FAIL: Test_Transfer (0.00s)
    --- FAIL: Test_Transfer/when_the_transfer_exceeds_the_daily_debit_limit (0.00s)
        --- FAIL: Test_Transfer/when_the_transfer_exceeds_the_daily_debit_limit/it_does_not_transfer_any_funds_from_the_account (0.00s)
            dogma.go:4: --- executing commands.OpenAccount command ---
            dogma.go:3: = 01  ∵ 01  ⋲ 01  ▼ ⚙    dispatching ● 2021-01-06T11:16:23+10:00 ● enabled: +aggregates +processes
            dogma.go:3: = 01  ∵ 01  ⋲ 01  ▼ ⚙    commands.OpenAccount? ● opening account A001 Anna Smith for customer C001
            dogma.go:3: = 01  ∵ 01  ⋲ 01  ▼ ∴    account A001 ● instance does not yet exist
            dogma.go:3: = 01  ∵ 01  ⋲ 01  ▼ ∴    account A001 ● instance created
            dogma.go:3: = 02  ∵ 01  ⋲ 01  ▲ ∴    account A001 ● recorded an event ● events.AccountOpened! ● opened account A001 Anna Smith for customer C001
            dogma.go:3: = 02  ∵ 01  ⋲ 01  ▼ ⚙    events.AccountOpened! ● opened account A001 Anna Smith for customer C001
            dogma.go:4: --- executing commands.OpenAccount command ---
            dogma.go:3: = 03  ∵ 03  ⋲ 03  ▼ ⚙    dispatching ● 2021-01-06T11:16:23+10:00 ● enabled: +aggregates +processes
            dogma.go:3: = 03  ∵ 03  ⋲ 03  ▼ ⚙    commands.OpenAccount? ● opening account A002 Bob Jones for customer C002
            dogma.go:3: = 03  ∵ 03  ⋲ 03  ▼ ∴    account A002 ● instance does not yet exist
            dogma.go:3: = 03  ∵ 03  ⋲ 03  ▼ ∴    account A002 ● instance created
            dogma.go:3: = 04  ∵ 03  ⋲ 03  ▲ ∴    account A002 ● recorded an event ● events.AccountOpened! ● opened account A002 Bob Jones for customer C002
            dogma.go:3: = 04  ∵ 03  ⋲ 03  ▼ ⚙    events.AccountOpened! ● opened account A002 Bob Jones for customer C002
            dogma.go:4: --- executing commands.Deposit command ---
            dogma.go:3: = 05  ∵ 05  ⋲ 05  ▼ ⚙    dispatching ● 2021-01-06T11:16:23+10:00 ● enabled: +aggregates +processes
            dogma.go:3: = 05  ∵ 05  ⋲ 05  ▼ ⚙    commands.Deposit? ● deposit D001: depositing $9100.00 into account A001
            dogma.go:3: = 05  ∵ 05  ⋲ 05  ▼ ∴    transaction D001 ● instance does not yet exist
            dogma.go:3: = 05  ∵ 05  ⋲ 05  ▼ ∴    transaction D001 ● instance created
            dogma.go:3: = 06  ∵ 05  ⋲ 05  ▲ ∴    transaction D001 ● recorded an event ● events.DepositStarted! ● deposit D001: started deposit of $9100.00 into account A001
            dogma.go:3: = 06  ∵ 05  ⋲ 05  ▼ ⚙    events.DepositStarted! ● deposit D001: started deposit of $9100.00 into account A001
            dogma.go:3: = 06  ∵ 05  ⋲ 05  ▼ ≡    deposit D001 ● instance does not yet exist
            dogma.go:3: = 06  ∵ 05  ⋲ 05  ▼ ≡    deposit D001 ● instance begun
            dogma.go:3: = 07  ∵ 06  ⋲ 05  ▲ ≡    deposit D001 ● executed a command ● commands.CreditAccount? ● deposit D001: crediting $9100.00 to account A001
            dogma.go:3: = 07  ∵ 06  ⋲ 05  ▼ ⚙    commands.CreditAccount? ● deposit D001: crediting $9100.00 to account A001
            dogma.go:3: = 07  ∵ 06  ⋲ 05  ▼ ∴    account A001 ● loaded an existing instance
            dogma.go:3: = 08  ∵ 07  ⋲ 05  ▲ ∴    account A001 ● recorded an event ● events.AccountCredited! ● deposit D001: credited $9100.00 to account A001
            dogma.go:3: = 08  ∵ 07  ⋲ 05  ▼ ⚙    events.AccountCredited! ● deposit D001: credited $9100.00 to account A001
            dogma.go:3: = 08  ∵ 07  ⋲ 05  ▼ ≡    transfer ● event ignored because it was not routed to any instance
            dogma.go:3: = 08  ∵ 07  ⋲ 05  ▼ ≡    withdrawal ● event ignored because it was not routed to any instance
            dogma.go:3: = 08  ∵ 07  ⋲ 05  ▼ ≡    deposit D001 ● loaded an existing instance
            dogma.go:3: = 09  ∵ 08  ⋲ 05  ▲ ≡    deposit D001 ● executed a command ● commands.ApproveDeposit? ● deposit D001: approving deposit of $9100.00 into account A001
            dogma.go:3: = 09  ∵ 08  ⋲ 05  ▼ ⚙    commands.ApproveDeposit? ● deposit D001: approving deposit of $9100.00 into account A001
            dogma.go:3: = 09  ∵ 08  ⋲ 05  ▼ ∴    transaction D001 ● loaded an existing instance
            dogma.go:3: = 10  ∵ 09  ⋲ 05  ▲ ∴    transaction D001 ● recorded an event ● events.DepositApproved! ● deposit D001: approved deposit of $9100.00 into account A001
            dogma.go:3: = 10  ∵ 09  ⋲ 05  ▼ ⚙    events.DepositApproved! ● deposit D001: approved deposit of $9100.00 into account A001
            dogma.go:3: = 10  ∵ 09  ⋲ 05  ▼ ≡    deposit D001 ● loaded an existing instance
            dogma.go:3: = 10  ∵ 09  ⋲ 05  ▼ ≡    deposit D001 ● instance ended
            dogma.go:4: --- expect executing commands.Transfer command to record a specific 'events.TransferDeclined' event ---
            dogma.go:3: = 11  ∵ 11  ⋲ 11  ▼ ⚙    dispatching ● 2021-01-06T11:16:23+10:00 ● enabled: +aggregates +processes
            dogma.go:3: = 11  ∵ 11  ⋲ 11  ▼ ⚙    commands.Transfer? ● transfer T001: transfering $9000.01 from account A001 to account A002
            dogma.go:3: = 11  ∵ 11  ⋲ 11  ▼ ∴    transaction T001 ● instance does not yet exist
            dogma.go:3: = 11  ∵ 11  ⋲ 11  ▼ ∴    transaction T001 ● instance created
            dogma.go:3: = 12  ∵ 11  ⋲ 11  ▲ ∴    transaction T001 ● recorded an event ● events.TransferStarted! ● transfer T001: started transfer of $9000.01 from account A001 to account A002
            dogma.go:3: = 12  ∵ 11  ⋲ 11  ▼ ⚙    events.TransferStarted! ● transfer T001: started transfer of $9000.01 from account A001 to account A002
            dogma.go:3: = 12  ∵ 11  ⋲ 11  ▼ ≡    transfer T001 ● instance does not yet exist
            dogma.go:3: = 12  ∵ 11  ⋲ 11  ▼ ≡    transfer T001 ● instance begun
            dogma.go:3: = 13  ∵ 12  ⋲ 11  ▲ ≡    transfer T001 ● scheduled a timeout for 2001-02-03T00:00:00Z ● domain.TransferReadyToProceed@ ● {T001 A001  900001 2001-02-03}
            dogma.go:3: = 13  ∵ 12  ⋲ 11  ▼ ⚙    domain.TransferReadyToProceed@ ● {T001 A001  900001 2001-02-03}
            dogma.go:3: = 13  ∵ 12  ⋲ 11  ▼ ≡    transfer T001 ● loaded an existing instance
            dogma.go:3: = 14  ∵ 13  ⋲ 11  ▲ ≡    transfer T001 ● executed a command ● commands.DebitAccount? ● transfer T001: debiting $9000.01 from account A001
            dogma.go:3: = 14  ∵ 13  ⋲ 11  ▼ ⚙    commands.DebitAccount? ● transfer T001: debiting $9000.01 from account A001
            dogma.go:3: = 14  ∵ 13  ⋲ 11  ▼ ∴    account A001 ● loaded an existing instance
            dogma.go:3: = 15  ∵ 14  ⋲ 11  ▲ ∴    account A001 ● recorded an event ● events.AccountDebited! ● transfer T001: debited $9000.01 from account A001
            dogma.go:3: = 15  ∵ 14  ⋲ 11  ▼ ⚙    events.AccountDebited! ● transfer T001: debited $9000.01 from account A001
            dogma.go:3: = 15  ∵ 14  ⋲ 11  ▼ ≡    transfer T001 ● loaded an existing instance
            dogma.go:3: = 16  ∵ 15  ⋲ 11  ▲ ≡    transfer T001 ● executed a command ● commands.ConsumeDailyDebitLimit? ● transfer T001: consuming $9000.01 from 2001-02-03 daily debit limit of account A001
            dogma.go:3: = 15  ∵ 14  ⋲ 11  ▼ ≡    withdrawal ● event ignored because it was not routed to any instance
            dogma.go:3: = 16  ∵ 15  ⋲ 11  ▼ ⚙    commands.ConsumeDailyDebitLimit? ● transfer T001: consuming $9000.01 from 2001-02-03 daily debit limit of account A001
            dogma.go:3: = 16  ∵ 15  ⋲ 11  ▼ ∴    daily-debit-limit 2001-02-03:A001 ● instance does not yet exist
panic: the 'daily-debit-limit' aggregate message handler behaved unexpectedly in domain.DailyDebitLimitHandler.HandleCommand(): recorded an invalid events.DailyDebitLimitExceeded event: DailyDebitLimitExceeded needs a valid total debits for day [recovered]
	panic: the 'daily-debit-limit' aggregate message handler behaved unexpectedly in domain.DailyDebitLimitHandler.HandleCommand(): recorded an invalid events.DailyDebitLimitExceeded event: DailyDebitLimitExceeded needs a valid total debits for day [recovered]
	panic: the 'daily-debit-limit' aggregate message handler behaved unexpectedly in domain.DailyDebitLimitHandler.HandleCommand(): recorded an invalid events.DailyDebitLimitExceeded event: DailyDebitLimitExceeded needs a valid total debits for day

goroutine 27 [running]:
testing.tRunner.func1.1(0x124bda0, 0xc0002f8900)
	/usr/local/Cellar/go/1.15.5/libexec/src/testing/testing.go:1072 +0x30d
testing.tRunner.func1(0xc000175800)
	/usr/local/Cellar/go/1.15.5/libexec/src/testing/testing.go:1075 +0x41a
panic(0x124bda0, 0xc0002f8900)
	/usr/local/Cellar/go/1.15.5/libexec/src/runtime/panic.go:969 +0x1b9
github.com/dogmatiq/testkit/engine/internal/panicx.EnrichUnexpectedMessage.func1(0x2a65098, 0xc0001cb3e0, 0x1262419, 0x17, 0x125fb51, 0xd, 0x1235100, 0x140f910, 0x1248f20, 0xc0002c9590)
	/Users/kevin/go/pkg/mod/github.com/dogmatiq/[email protected]/engine/internal/panicx/unexpectedmessage.go:74 +0x1a5
panic(0x124bda0, 0xc0002f8900)
	/usr/local/Cellar/go/1.15.5/libexec/src/runtime/panic.go:969 +0x1b9
github.com/dogmatiq/testkit/engine/internal/aggregate.(*scope).RecordEvent(0xc0002f8870, 0x124cfe0, 0xc0001cb860)
	/Users/kevin/go/pkg/mod/github.com/dogmatiq/[email protected]/engine/internal/aggregate/scope.go:62 +0xaaa
github.com/dogmatiq/example/domain.(*dailyDebitLimit).Consume(0xc0003521b8, 0x12a6700, 0xc0002f8870, 0x125de04, 0x4, 0x125dda0, 0x4, 0x125e96c, 0x8, 0xdbba1, ...)
	/Users/kevin/grit/github.com/dogmatiq/example/domain/dailydebitlimit.go:23 +0x16d
github.com/dogmatiq/example/domain.DailyDebitLimitHandler.HandleCommand(0x12a2440, 0xc0003521b8, 0x12a6700, 0xc0002f8870, 0x1248f20, 0xc0002c9590)
	/Users/kevin/grit/github.com/dogmatiq/example/domain/dailydebitlimit.go:101 +0x114
github.com/dogmatiq/testkit/engine/internal/aggregate.(*Controller).Handle.func3()
	/Users/kevin/go/pkg/mod/github.com/dogmatiq/[email protected]/engine/internal/aggregate/controller.go:133 +0xaf
github.com/dogmatiq/testkit/engine/internal/panicx.EnrichUnexpectedMessage(0x2a65098, 0xc0001cb3e0, 0x1262419, 0x17, 0x125fb51, 0xd, 0x1235100, 0x140f910, 0x1248f20, 0xc0002c9590, ...)
	/Users/kevin/go/pkg/mod/github.com/dogmatiq/[email protected]/engine/internal/panicx/unexpectedmessage.go:77 +0x10e
github.com/dogmatiq/testkit/engine/internal/aggregate.(*Controller).Handle(0xc000314ac0, 0x12a6480, 0xc000014120, 0x12a28a0, 0xc00033fd80, 0xbff561b9f5ef5f80, 0x6d2bd9, 0x13e0300, 0xc000338790, 0x0, ...)
	/Users/kevin/go/pkg/mod/github.com/dogmatiq/[email protected]/engine/internal/aggregate/controller.go:126 +0x74c
github.com/dogmatiq/testkit/engine.(*Engine).handle(0xc0002c9220, 0x12a6480, 0xc000014120, 0xc0002fd5c0, 0xc000338790, 0x12a66c0, 0xc000314ac0, 0x0, 0x0, 0x0, ...)
	/Users/kevin/go/pkg/mod/github.com/dogmatiq/[email protected]/engine/engine.go:346 +0x34b
github.com/dogmatiq/testkit/engine.(*Engine).dispatch(0xc0002c9220, 0x12a6480, 0xc000014120, 0xc0002fd5c0, 0xc00000eaa0, 0x0, 0x0, 0x6d2bd9, 0x13e0300)
	/Users/kevin/go/pkg/mod/github.com/dogmatiq/[email protected]/engine/engine.go:288 +0x325
github.com/dogmatiq/testkit/engine.(*Engine).Dispatch(0xc0002c9220, 0x12a6480, 0xc000014120, 0x1249220, 0xc0002c9360, 0xc00012c680, 0x5, 0x8, 0x0, 0x0)
	/Users/kevin/go/pkg/mod/github.com/dogmatiq/[email protected]/engine/engine.go:234 +0x61e
github.com/dogmatiq/testkit.dispatchAction.Do(0x125e530, 0x7, 0x1249220, 0xc0002c9360, 0x13b91d0, 0x3d, 0x13ba911, 0x45, 0x108, 0x12a6480, ...)
	/Users/kevin/go/pkg/mod/github.com/dogmatiq/[email protected]/action.dispatch.go:88 +0x35c
github.com/dogmatiq/testkit.(*Test).doAction(0xc0002b5b80, 0x12a6980, 0xc0002c93b0, 0xc000151c00, 0x1, 0x1, 0x12aab40, 0x1249520)
	/Users/kevin/go/pkg/mod/github.com/dogmatiq/[email protected]/test.go:183 +0x2ea
github.com/dogmatiq/testkit.(*Test).Expect.func1(0x12a6640, 0xc000338370, 0xc0002b5b80, 0x12a6980, 0xc0002c93b0, 0x0, 0x0)
	/Users/kevin/go/pkg/mod/github.com/dogmatiq/[email protected]/test.go:114 +0xf0
github.com/dogmatiq/testkit.(*Test).Expect(0xc0002b5b80, 0x12a6980, 0xc0002c93b0, 0x12a4740, 0xc0002fd540, 0xc00000e970)
	/Users/kevin/go/pkg/mod/github.com/dogmatiq/[email protected]/test.go:115 +0x369
github.com/dogmatiq/example/domain_test.Test_Transfer.func4.1(0xc000175800)
	/Users/kevin/grit/github.com/dogmatiq/example/domain/transfer_test.go:263 +0x49b
testing.tRunner(0xc000175800, 0x126db30)
	/usr/local/Cellar/go/1.15.5/libexec/src/testing/testing.go:1123 +0xef
created by testing.(*T).Run
	/usr/local/Cellar/go/1.15.5/libexec/src/testing/testing.go:1168 +0x2b3
FAIL	github.com/dogmatiq/example/domain	0.285s
?   	github.com/dogmatiq/example/lib/bank	[no test files]
?   	github.com/dogmatiq/example/messages	[no test files]
?   	github.com/dogmatiq/example/messages/commands	[no test files]
?   	github.com/dogmatiq/example/messages/events	[no test files]
ok  	github.com/dogmatiq/example/projections	0.349s
FAIL
make: *** [test] Error 1