commanded / eventstore

Event store using PostgreSQL for persistence
MIT License
1.04k stars 142 forks source link

Match Error Between event_store and Postgrex.Error #240

Closed aeturnum closed 3 years ago

aeturnum commented 3 years ago

I ran into this error when trying to test the base case of a fresh commanded setup. This is on postgres 10.15 on the official apline image.

I've created a small sample project that reproduces this error for me: https://github.com/aeturnum/eventstore_problem

I'm just not sure how to further diagnose this issue.

Here is the full error as reproduced by running the test in the above project:

`mix test` output ```elixir ddrexler@Drexbook-Pro:commanded_test| git:(upstream ⚡ master)$ mix test 09:52:43.781 [debug] Attempting to start Postgrex 09:52:43.821 [debug] Successfully started Postgrex (#PID<0.234.0>) 09:52:43.821 [debug] Attempting to start Postgrex 09:52:43.822 [debug] Successfully started Postgrex (#PID<0.247.0>) 09:52:43.828 [debug] Attempting to start Postgrex.Notifications 09:52:43.832 [debug] Successfully started Postgrex.Notifications (#PID<0.258.0>) 09:52:44.108 [debug] Locating aggregate process for `CommandedTest.Credits.AccountCredits` with UUID "test id" 09:52:44.131 [debug] CommandedTest.Credits.AccountCredits executing command: %CommandedTest.Credits.InitAccount{account_id: "test id"} 09:52:44.225 [error] ** (MatchError) no match of right hand side value: %Postgrex.Error{connection_id: 21677, message: nil, postgres: %{code: :object_not_in_prerequisite_state, detail: "The tuple structure of a not-yet-assigned record is indeterminate.", file: "pl_exec.c", line: "4905", message: "record \"old\" is not assigned yet", pg_code: "55000", routine: "exec_eval_datum", severity: "ERROR", unknown: "ERROR", where: "PL/pgSQL function notify_events() line 14 at assignment"}, query: nil} (eventstore 1.3.1) lib/event_store/storage/appender.ex:159: EventStore.Storage.Appender.handle_response/1 (eventstore 1.3.1) lib/event_store/storage/appender.ex:27: anonymous fn/5 in EventStore.Storage.Appender.append/4 (elixir 1.11.4) lib/enum.ex:804: anonymous fn/3 in Enum.each/2 (elixir 1.11.4) lib/enum.ex:3473: anonymous fn/3 in Enum.each/2 (elixir 1.11.4) lib/stream.ex:1597: anonymous fn/3 in Enumerable.Stream.reduce/3 (elixir 1.11.4) lib/stream.ex:285: Stream.after_chunk_while/2 (elixir 1.11.4) lib/stream.ex:1626: Enumerable.Stream.do_done/2 (elixir 1.11.4) lib/enum.ex:3473: Enum.each/2 (eventstore 1.3.1) lib/event_store/storage/appender.ex:24: EventStore.Storage.Appender.append/4 (eventstore 1.3.1) lib/event_store/streams/stream.ex:12: EventStore.Streams.Stream.append_to_stream/5 (commanded 1.2.0) lib/commanded/aggregates/aggregate.ex:491: Commanded.Aggregates.Aggregate.persist_events/4 (commanded 1.2.0) lib/commanded/aggregates/aggregate.ex:466: Commanded.Aggregates.Aggregate.execute_command/2 (commanded 1.2.0) lib/commanded/aggregates/aggregate.ex:231: Commanded.Aggregates.Aggregate.handle_call/3 (stdlib 3.15) gen_server.erl:721: :gen_server.try_handle_call/4 (stdlib 3.15) gen_server.erl:750: :gen_server.handle_msg/6 (stdlib 3.15) proc_lib.erl:226: :proc_lib.init_p_do_apply/3 09:52:44.229 [error] GenServer {CommandedTest.CreditApp.LocalRegistry, {CommandedTest.CreditApp, CommandedTest.Credits.AccountCredits, "test id"}} terminating ** (stop) %MatchError{term: %Postgrex.Error{connection_id: 21677, message: nil, postgres: %{code: :object_not_in_prerequisite_state, detail: "The tuple structure of a not-yet-assigned record is indeterminate.", file: "pl_exec.c", line: "4905", message: "record \"old\" is not assigned yet", pg_code: "55000", routine: "exec_eval_datum", severity: "ERROR", unknown: "ERROR", where: "PL/pgSQL function notify_events() line 14 at assignment"}, query: nil}} Last message (from #PID<0.322.0>): {:execute_command, %Commanded.Aggregates.ExecutionContext{causation_id: "ab64a75c-16ad-47da-a320-177231cc224e", command: %CommandedTest.Credits.InitAccount{account_id: "test id"}, correlation_id: "31d5ff54-f49e-426c-bd8f-997c8f84f31b", function: :execute, handler: CommandedTest.Credits.AccountCredits, lifespan: Commanded.Aggregates.DefaultLifespan, metadata: %{}, retry_attempts: 10, returning: false}} State: %Commanded.Aggregates.Aggregate{aggregate_module: CommandedTest.Credits.AccountCredits, aggregate_state: %CommandedTest.Credits.AccountCredits{account_id: nil, balance: 0, history: [], open_adjustments: %{}}, aggregate_uuid: "test id", aggregate_version: 0, application: CommandedTest.CreditApp, lifespan_timeout: {:stop, %MatchError{term: %Postgrex.Error{connection_id: 21677, message: nil, postgres: %{code: :object_not_in_prerequisite_state, detail: "The tuple structure of a not-yet-assigned record is indeterminate.", file: "pl_exec.c", line: "4905", message: "record \"old\" is not assigned yet", pg_code: "55000", routine: "exec_eval_datum", severity: "ERROR", unknown: "ERROR", where: "PL/pgSQL function notify_events() line 14 at assignment"}, query: nil}}}, snapshotting: %Commanded.Snapshotting{application: CommandedTest.CreditApp, snapshot_every: nil, snapshot_module_version: 1, snapshot_version: 0, source_uuid: "test id"}} Client #PID<0.322.0> is alive (stdlib 3.15) gen.erl:233: :gen.do_call/4 (elixir 1.11.4) lib/gen_server.ex:1024: GenServer.call/3 (commanded 1.2.0) lib/commanded/aggregates/aggregate.ex:137: Commanded.Aggregates.Aggregate.execute/5 (elixir 1.11.4) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2 (elixir 1.11.4) lib/task/supervised.ex:35: Task.Supervised.reply/5 (stdlib 3.15) proc_lib.erl:226: :proc_lib.init_p_do_apply/3 1) test Open Account (CommandedTest.CustomerListTest) test/account_aggregator_test.exs:16 ** (MatchError) no match of right hand side value: {:error, %MatchError{term: %Postgrex.Error{connection_id: 21677, message: nil, postgres: %{code: :object_not_in_prerequisite_state, detail: "The tuple structure of a not-yet-assigned record is indeterminate.", file: "pl_exec.c", line: "4905", message: "record \"old\" is not assigned yet", pg_code: "55000", routine: "exec_eval_datum", severity: "ERROR", unknown: "ERROR", where: "PL/pgSQL function notify_events() line 14 at assignment"}, query: nil}}} code: :ok = CreditApp.dispatch(%Credits.InitAccount{account_id: "test id"}) stacktrace: test/account_aggregator_test.exs:17: (test) Finished in 0.2 seconds 1 test, 1 failure Randomized with seed 964669 ```

Some other details that might be useful:

SQL statement generated from template ```sql WITH new_events_indexes (event_id, index, stream_version) AS ( VALUES ($3::uuid, $10::int, $11::bigint) ), events AS ( INSERT INTO public.events ( event_id, event_type, causation_id, correlation_id, data, metadata, created_at ) VALUES ($3, $4, $5, $6, $7, $8, $9) ), stream AS ( INSERT INTO public.streams (stream_uuid, stream_version) VALUES ($1, $2::bigint) returning stream_id ), source_stream_events AS ( INSERT INTO public.stream_events ( event_id, stream_id, stream_version, original_stream_id, original_stream_version ) SELECT new_events_indexes.event_id, stream.stream_id, new_events_indexes.stream_version, stream.stream_id, new_events_indexes.stream_version FROM new_events_indexes, stream ), linked_stream AS ( UPDATE public.streams SET stream_version = stream_version + $2::bigint WHERE stream_id = 0 RETURNING stream_version - $2::bigint as initial_stream_version ) INSERT INTO public.stream_events ( event_id, stream_id, stream_version, original_stream_id, original_stream_version ) SELECT new_events_indexes.event_id, 0, linked_stream.initial_stream_version + new_events_indexes.index, stream.stream_id, new_events_indexes.stream_version FROM new_events_indexes, linked_stream, stream; ```
SQL parameters (with associated fields in the SQL statement) ```elixir [ "test id", // stream_uuid 1, // stream_version <<44, 220, 233, 219, 162, 170, 70, 136, 186, 60, 85, 7, 173, 168, 248, 152>>, // event_id "Elixir.CommandedTest.Credits.CreditsSetTo", // event_type <<21, 144, 181, 246, 217, 241, 67, 72, 189, 72, 171, 185, 97, 118, 199, 216>>, //causation_id <<200, 10, 143, 86, 22, 29, 73, 166, 155, 73, 201, 4, 92, 137, 146, 95>>, // correlation_id "{\"account_id\":\"test id\",\"new_balance\":0,\"prev_balance\":0,\"reason\":null,\"timestamp\":\"2021-06-07T22:32:46.944721Z\"}", // data "{}", // metadata ~U[2021-06-07 22:32:46.971443Z], // created_at 1, // index 1 // stream_version ] ```
Postgrex Error ```elixir %Postgrex.Error{ connection_id: 1717, message: nil, postgres: %{ code: :object_not_in_prerequisite_state, detail: "The tuple structure of a not-yet-assigned record is indeterminate.", file: "pl_exec.c", line: "4905", message: "record \"old\" is not assigned yet", pg_code: "55000", routine: "exec_eval_datum", severity: "ERROR", unknown: "ERROR", where: "PL/pgSQL function notify_events() line 14 at assignment" }, query: nil } ```
slashdotdash commented 3 years ago

Thanks for the bug report @aeturnum. I believe this is related to the event_notification trigger. If you can upgrade to Postgres v12 or later you should not encounter the problem.