Event handler not receiving event

[losttime]

I have an umbrella app that contains 2 apps. I'm using Elixir 1.8.1, which I understand isn't officially supported by extreme and would be happy to switch back if I need to.

The first app receives HTTP input and generates a command. The aggregate accepts the command and generates an event that is published to the event store. The aggregate then processes the event to update its internal state.

I am attempting to configure an event handler in the second app to process the same event and perform some other work (just log for now). I can see that the event handler is starting up and subscribing to the event store, but the events don't come in.

My event handler:

defmodule Driven.Worker do
  @moduledoc """
  Listens for events and acts on them
  """

  use Commanded.Event.Handler, name: "DrivenHandler"
  alias Api.Events.UserRegistered
  require Logger

  def handle(%UserRegistered{}, _metadata) do
    Logger.info("Handling Driven event")
    :ok
  end
end

I've tracked the event down to Extreme.Subscription.def handle_cast/2 when the status is :subscribed. I can't tell where the message goes from there.

I'm going to keep looking into it, but I'd appreciate any pointers anyone might have.

[losttime]

The only thing I've been able to figure out so far is that if I shutdown my app and rename the handler, the event comes through when I start the app back up. Subsequent events to not come through.

[losttime]

I'm now on Elixir 1.7.4 and EventStore 4.0.3 (using EventStore protocol 4), but thing don't seem to have changed.

It's looking like my event handler creates and/or joins a "persistent subscription", but the event that appears (from EventStore?) for the persistent subscription is mostly nil values. There is another event that appears (from EventStore?) at the same time that is not a persistent subscription event, but it contains all the correct values. Because that second event is not a persistent subscription event it doesn't get delivered to my event handler.

Here are those 2 events

%Extreme.Msg.PersistentSubscriptionStreamEventAppeared{
  event: %Extreme.Msg.ResolvedIndexedEvent{
    event: %Extreme.Msg.EventRecord{
      created: nil,
      created_epoch: nil,
      data: nil,
      data_content_type: nil,
      event_id: nil,
      event_number: nil,
      event_stream_id: nil,
      event_type: nil,
      metadata: nil,
      metadata_content_type: nil
    },
    link: %Extreme.Msg.EventRecord{
      created: 636871542507912100,
      created_epoch: 1551557450791,
      data: "0@commandeddev-fooo@example.com",
      data_content_type: 0,
      event_id: <<45, 191, 11, 100, 38, 238, 146, 67, 172, 41, 182, 7, 226, 190,
        204, 181>>,
      event_number: 14,
      event_stream_id: "$ce-commandeddev",
      event_type: "$>",
      metadata: "{\"$v\":\"3:-1:1:3\",\"$c\":9337794,\"$p\":9337794,\"$o\":\"commandeddev-fooo@example.com\",\"$causedBy\":\"8edfd556-6faf-7741-9fd6-400139dbf69a\"}",
      metadata_content_type: 0
    }
  }
}

%Extreme.Msg.StreamEventAppeared{
  event: %Extreme.Msg.ResolvedEvent{
    commit_position: 9338354,
    event: %Extreme.Msg.EventRecord{
      created: 636871542507640860,
      created_epoch: 1551557450764,
      data: "{\"email_address\":\"fooo@example.com\",\"password\":\"<supersecret>\"}",
      data_content_type: 0,
      event_id: <<86, 213, 223, 142, 175, 111, 65, 119, 159, 214, 64, 1, 57,
        219, 246, 154>>,
      event_number: 0,
      event_stream_id: "commandeddev-fooo@example.com",
      event_type: "Elixir.Api.Events.UserRegistered",
      metadata: "{\"$causationId\":\"77cfc3bf-7346-4124-8f32-9efd0ed57831\",\"$correlationId\":\"3ef252d2-dfda-423d-942e-e88dca21749a\"}",
      metadata_content_type: 0
    },
    link: %Extreme.Msg.EventRecord{
      created: 636871542507912100,
      created_epoch: 1551557450791,
      data: "0@commandeddev-fooo@example.com",
      data_content_type: 0,
      event_id: <<45, 191, 11, 100, 38, 238, 146, 67, 172, 41, 182, 7, 226, 190,
        204, 181>>,
      event_number: 14,
      event_stream_id: "$ce-commandeddev",
      event_type: "$>",
      metadata: "{\"$v\":\"3:-1:1:3\",\"$c\":9337794,\"$p\":9337794,\"$o\":\"commandeddev-fooo@example.com\",\"$causedBy\":\"8edfd556-6faf-7741-9fd6-400139dbf69a\"}",
      metadata_content_type: 0
    },
    prepare_position: 9338354
  }
}

Still looking. Any thoughts or insights would be helpful.

[slashdotdash]

If you can create an example repo exhibiting the issue then I can take a look for you.

[losttime]

I have created this repo that reproduces the problem on my machine (MacBook Pro, MacOS 10.14.3) https://github.com/losttime/commanded_poc

I'd appreciate any insight into what I may have done wrong.

[slashdotdash]

@losttime I've finally tracked down the root cause of the issue, it's because the aggregate identity (and stream name) contains an at (@) symbol.

If you try without, such as just example, it works:

iex> Trial.register("example", "password")      

11:02:54.582 [debug] Locating aggregate process for `Trial.Aggregates.User` with UUID "example"
executing registration command when existing is nil

11:02:54.602 [debug] Trial.Aggregates.User<example@0> executing command: %Trial.Commands.RegisterUser{email_address: "example", password: "password"}
applying registration event

11:02:54.604 [debug] Extreme event store attempting to append to stream "commandeddev-example" 1 event(s)

11:02:54.623 [info]  Command dispatched
:ok
11:02:54.649 [debug] Persistent subscription "$ce-commandeddev::driven" event appeared: %Extreme.Msg.PersistentSubscriptionStreamEventAppeared{event: %Extreme.Msg.ResolvedIndexedEvent{event: %Extreme.Msg.EventRecord{created: 636872941746349360, created_epoch: 1551697374634, data: "{\"email_address\":\"example\",\"password\":\"password\"}", data_content_type: 0, event_id: <<175, 154, 214, 80, 50, 129, 69, 113, 164, 128, 26, 163, 164, 157, 158, 171>>, event_number: 0, event_stream_id: "commandeddev-example", event_type: "Elixir.Trial.Events.UserRegistered", metadata: "{\"$causationId\":\"a3103772-cf73-495a-8783-e37d51870d2d\",\"$correlationId\":\"9f5672e3-d315-4f85-a843-82cef479fc19\"}", metadata_content_type: 0}, link: %Extreme.Msg.EventRecord{created: 636872941746525170, created_epoch: 1551697374652, data: "0@commandeddev-example", data_content_type: 0, event_id: <<240, 212, 172, 205, 139, 145, 4, 64, 139, 182, 9, 63, 239, 159, 15, 143>>, event_number: 0, event_stream_id: "$ce-commandeddev", event_type: "$>", metadata: "{\"$v\":\"3:-1:1:3\",\"$c\":56012,\"$p\":56012,\"$o\":\"commandeddev-example\",\"$causedBy\":\"50d69aaf-8132-7145-a480-1aa3a49d9eab\"}", metadata_content_type: 0}}} correlation_id: <<9, 197, 122, 142, 62, 109, 17, 233, 162, 35, 242, 24, 152, 24, 217, 98>>

11:02:54.649 [debug] Extreme event store subscription "driven" received event: %Extreme.Msg.ResolvedIndexedEvent{event: %Extreme.Msg.EventRecord{created: 636872941746349360, created_epoch: 1551697374634, data: "{\"email_address\":\"example\",\"password\":\"password\"}", data_content_type: 0, event_id: <<175, 154, 214, 80, 50, 129, 69, 113, 164, 128, 26, 163, 164, 157, 158, 171>>, event_number: 0, event_stream_id: "commandeddev-example", event_type: "Elixir.Trial.Events.UserRegistered", metadata: "{\"$causationId\":\"a3103772-cf73-495a-8783-e37d51870d2d\",\"$correlationId\":\"9f5672e3-d315-4f85-a843-82cef479fc19\"}", metadata_content_type: 0}, link: %Extreme.Msg.EventRecord{created: 636872941746525170, created_epoch: 1551697374652, data: "0@commandeddev-example", data_content_type: 0, event_id: <<240, 212, 172, 205, 139, 145, 4, 64, 139, 182, 9, 63, 239, 159, 15, 143>>, event_number: 0, event_stream_id: "$ce-commandeddev", event_type: "$>", metadata: "{\"$v\":\"3:-1:1:3\",\"$c\":56012,\"$p\":56012,\"$o\":\"commandeddev-example\",\"$causedBy\":\"50d69aaf-8132-7145-a480-1aa3a49d9eab\"}", metadata_content_type: 0}}

11:02:54.700 [debug] Trial.Aggregates.User<example@1> received events: [%Commanded.EventStore.RecordedEvent{causation_id: "a3103772-cf73-495a-8783-e37d51870d2d", correlation_id: "9f5672e3-d315-4f85-a843-82cef479fc19", created_at: ~N[2019-03-04 11:02:54.634], data: %Trial.Events.UserRegistered{email_address: "example", password: "password"}, event_id: "af9ad650-3281-4571-a480-1aa3a49d9eab", event_number: 1, event_type: "Elixir.Trial.Events.UserRegistered", metadata: %{}, stream_id: "example", stream_version: 1}]
Handling Driven event

11:02:54.700 [debug] Trial.Handlers.Driven received events: [%Commanded.EventStore.RecordedEvent{causation_id: "a3103772-cf73-495a-8783-e37d51870d2d", correlation_id: "9f5672e3-d315-4f85-a843-82cef479fc19", created_at: ~N[2019-03-04 11:02:54.634], data: %Trial.Events.UserRegistered{email_address: "example", password: "password"}, event_id: "af9ad650-3281-4571-a480-1aa3a49d9eab", event_number: 1, event_type: "Elixir.Trial.Events.UserRegistered", metadata: %{}, stream_id: "example", stream_version: 1}]

11:02:54.700 [info]  Handling Driven event

11:02:54.700 [debug] Trial.Handlers.Driven confirming receipt of event #1

11:02:54.700 [debug] Extreme event store subscription "driven" ack event: 1

11:02:54.700 [debug] Persistent subscription "$ce-commandeddev::driven" ack event id: <<240, 212, 172, 205, 139, 145, 4, 64, 139, 182, 9, 63, 239, 159, 15, 143>> correlation_id: <<9, 197, 122, 142, 62, 109, 17, 233, 162, 35, 242, 24, 152, 24, 217, 98>>

I don't know why the @ symbol causes a problem, it needs further investigation.

[losttime]

I have confirmed that you are correct. That was so quick! Thanks for lending your experience to help me 🥇

Would you suggest I focus on coming up with a more suitable way to key the entities (because I admit my attempt was pretty naive), or help identify why the presence of @ is so troublesome and how to overcome it?

[slashdotdash]

For now I'd suggest using an alternative identity (e.g. UUID.uuid4()) while I investigate why @ causes a problem.