commanded / eventstore

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

`EventStore.append_to_stream` is not able to append more than 1000 events to a new stream. #283

Open thomasdziedzic opened 5 months ago

thomasdziedzic commented 5 months ago

While investigating the cause for https://github.com/commanded/commanded/issues/554 I discovered that the issue might be deeper in the stack. So I wrote a test case for EventStore and was able to reproduce that issue in this project.

I wrote the following reproducible test case:

diff --git a/test/append_to_stream_test.exs b/test/append_to_stream_test.exs
index d3c3e9c..bd6d625 100644
--- a/test/append_to_stream_test.exs
+++ b/test/append_to_stream_test.exs
@@ -15,6 +15,16 @@ defmodule EventStore.AppendToStreamTest do
       assert length(events) == 3
     end

+    test "should handle more than 1000 events" do
+      stream_uuid = UUID.uuid4()
+      events = EventFactory.create_events(1001)
+
+      assert :ok = EventStore.append_to_stream(stream_uuid, :any_version, events)
+
+      assert {:ok, events} = EventStore.read_stream_forward(stream_uuid)
+      assert length(events) == 1001
+    end
+
     test "concurrently should succeed" do
       stream_uuid = UUID.uuid4()
       events = EventFactory.create_events(1)

This fails with:

$ mix test test/append_to_stream_test.exs:18
Excluding tags: [:test]
Including tags: [location: {"test/append_to_stream_test.exs", 18}]

  1) test append to new stream using `:any_version` should handle more than 1000 events (EventStore.AppendToStreamTest)
     test/append_to_stream_test.exs:18
     match (=) failed
     code:  assert :ok = EventStore.append_to_stream(stream_uuid, :any_version, events)
     left:  :ok
     right: {:error, :already_retried_once}
     stacktrace:
       test/append_to_stream_test.exs:22: (test)

     The following output was logged:

     09:54:49.482 [warning] Failed to append events to stream "689078a4-9a9b-46e8-b67e-917c13540a33" due to: :duplicate_stream_uuid

     09:54:49.529 [warning] Failed to append events to stream "689078a4-9a9b-46e8-b67e-917c13540a33" due to: :duplicate_stream_uuid

Finished in 0.3 seconds (0.00s async, 0.3s sync)
13 tests, 1 failure, 12 excluded
thomasdziedzic commented 5 months ago

In fact I didn't need to write a test, I found an already failing test in the suite: Note the line number is off due to my patch above. The actual test is located here: https://github.com/commanded/eventstore/blob/master/test/append_to_stream_test.exs#L166

$ mix test test/append_to_stream_test.exs:176
Excluding tags: [:test]
Including tags: [location: {"test/append_to_stream_test.exs", 176}]

  1) test should append many events to a stream (EventStore.AppendToStreamTest)
     test/append_to_stream_test.exs:176
     match (=) failed
     code:  assert :ok = EventStore.append_to_stream(stream_uuid, 0, events, timeout: :infinity)
     left:  :ok
     right: {:error, :already_retried_once}
     stacktrace:
       test/append_to_stream_test.exs:180: (test)

     The following output was logged:

     10:00:55.951 [warning] Failed to append events to stream "7afe5369-4386-4f81-823c-22e8ced37697" due to: :duplicate_stream_uuid

     10:00:56.029 [warning] Failed to append events to stream "7afe5369-4386-4f81-823c-22e8ced37697" due to: :duplicate_stream_uuid

Finished in 0.4 seconds (0.00s async, 0.4s sync)
13 tests, 1 failure, 12 excluded
thomasdziedzic commented 5 months ago

I think I found out why this regression was introduced. CI runs mix test.all but I didn't see any logs of the slow tests being run in CI. I tried running mix test.all locally and indeed they all pass because the slow tests don't run. I tried to narrow the problem down and found that if I have test.all defined as "test.all": ["test", "test --only slow"], then the slow tests don't run. But if I have "test.all": ["test --only slow"], then the slow tests do run and the expected failure shows up. I'm not exactly sure why the slow tests get skipped when there's a previous test that gets run.

jdewar commented 1 month ago

I'm not exactly sure why the slow tests get skipped when there's a previous test that gets run.

Search "Mix tasks are designed to run only once" on https://hexdocs.pm/mix/1.17.2/Mix.html

tl;dr the 'test' task must be explicitly reenabled, eg.

another_alias: [
  "format --check-formatted priv/hello1.exs",
  "cmd priv/world.sh",
  fn _ -> Mix.Task.reenable("format") end,
  "format --check-formatted priv/hello2.exs"
]

edit: or maybe I misunderstood the confusion. the reason that some of them are skipped is because of the defaults: https://github.com/commanded/eventstore/blob/master/test/test_helper.exs