search

pawelkaczor / akka-ddd

Akka CQRS/ES framework
https://newicom.pl/akka-ddd/
MIT License
352 stars 61 forks source link

[view-update] StreamSubscriptionActor throws CommandNotExpectedException #1

Closed pawelkaczor closed 9 years ago

pawelkaczor commented 9 years ago

Question asked on Event Store forum: https://groups.google.com/forum/#!topic/event-store/jG68qEXaO80

pawelkaczor commented 9 years ago

Log messages from pl.newicom.dddd.view.sql.SqlViewUpdateServiceIntegrationSpec:

/opt/devel/jdk1.8.0_25/bin/java -Didea.launcher.port=7535 -Didea.launcher.bin.path=/opt/devel/idea-IU-139.224.1/bin -Dfile.encoding=UTF-8 -classpath /home/newion/.IntelliJIdea14/config/plugins/Scala/lib/scala-plugin-runners.jar:/home/newion/.IntelliJIdea14/config/plugins/Scala/lib/Runners.jar:/opt/devel/jdk1.8.0_25/jre/lib/jce.jar:/opt/devel/jdk1.8.0_25/jre/lib/deploy.jar:/opt/devel/jdk1.8.0_25/jre/lib/jfxswt.jar:/opt/devel/jdk1.8.0_25/jre/lib/jsse.jar:/opt/devel/jdk1.8.0_25/jre/lib/resources.jar:/opt/devel/jdk1.8.0_25/jre/lib/javaws.jar:/opt/devel/jdk1.8.0_25/jre/lib/rt.jar:/opt/devel/jdk1.8.0_25/jre/lib/charsets.jar:/opt/devel/jdk1.8.0_25/jre/lib/management-agent.jar:/opt/devel/jdk1.8.0_25/jre/lib/jfr.jar:/opt/devel/jdk1.8.0_25/jre/lib/plugin.jar:/opt/devel/jdk1.8.0_25/jre/lib/ext/sunec.jar:/opt/devel/jdk1.8.0_25/jre/lib/ext/cldrdata.jar:/opt/devel/jdk1.8.0_25/jre/lib/ext/dnsns.jar:/opt/devel/jdk1.8.0_25/jre/lib/ext/nashorn.jar:/opt/devel/jdk1.8.0_25/jre/lib/ext/sunpkcs11.jar:/opt/devel/jdk1.8.0_25/jre/lib/ext/sunjce_provider.jar:/opt/devel/jdk1.8.0_25/jre/lib/ext/localedata.jar:/opt/devel/jdk1.8.0_25/jre/lib/ext/jfxrt.jar:/opt/devel/jdk1.8.0_25/jre/lib/ext/zipfs.jar:/home/newion/Projects/akka-ddd/view-update-sql/target/scala-2.11/test-classes:/home/newion/Projects/akka-ddd/view-update-sql/target/scala-2.11/classes:/home/newion/Projects/akka-ddd/view-update/target/scala-2.11/classes:/home/newion/Projects/akka-ddd/akka-ddd-messaging/target/scala-2.11/classes:/home/newion/.ivy2/cache/com.github.nscala-time/nscala-time_2.11/jars/nscala-time_2.11-1.4.0.jar:/home/newion/.ivy2/cache/com.typesafe/config/bundles/config-1.2.1.jar:/home/newion/.ivy2/cache/joda-time/joda-time/jars/joda-time-2.4.jar:/home/newion/.ivy2/cache/org.scala-lang/scala-library/jars/scala-library-2.11.5.jar:/home/newion/.ivy2/cache/com.thoughtworks.paranamer/paranamer/jars/paranamer-2.6.jar:/home/newion/.ivy2/cache/org.joda/joda-convert/jars/joda-convert-1.6.jar:/home/newion/.ivy2/cache/org.json4s/json4s-ast_2.11/jars/json4s-ast_2.11-3.2.11.jar:/home/newion/.ivy2/cache/org.json4s/json4s-core_2.11/jars/json4s-core_2.11-3.2.11.jar:/home/newion/.ivy2/cache/org.json4s/json4s-ext_2.11/jars/json4s-ext_2.11-3.2.11.jar:/home/newion/.ivy2/cache/org.json4s/json4s-native_2.11/jars/json4s-native_2.11-3.2.11.jar:/home/newion/.ivy2/cache/org.scala-lang/scala-compiler/jars/scala-compiler-2.11.0.jar:/home/newion/.ivy2/cache/org.scala-lang/scala-reflect/jars/scala-reflect-2.11.0.jar:/home/newion/.ivy2/cache/org.scala-lang/scalap/jars/scalap-2.11.0.jar:/home/newion/.ivy2/cache/org.scala-lang.modules/scala-parser-combinators_2.11/bundles/scala-parser-combinators_2.11-1.0.1.jar:/home/newion/.ivy2/cache/org.scala-lang.modules/scala-xml_2.11/bundles/scala-xml_2.11-1.0.1.jar:/home/newion/.ivy2/cache/com.typesafe.akka/akka-actor_2.11/jars/akka-actor_2.11-2.4-SNAPSHOT.jar:/home/newion/Projects/akka-ddd/eventstore-akka-persistence/target/scala-2.11/classes:/home/newion/.ivy2/cache/com.google.protobuf/protobuf-java/bundles/protobuf-java-2.5.0.jar:/home/newion/.ivy2/cache/commons-codec/commons-codec/jars/commons-codec-1.8.jar:/home/newion/.ivy2/cache/org.apache.directory.studio/org.apache.commons.codec/jars/org.apache.commons.codec-1.8.jar:/home/newion/.ivy2/cache/org.fusesource.hawtjni/hawtjni-runtime/jars/hawtjni-runtime-1.8.jar:/home/newion/.ivy2/cache/org.fusesource.leveldbjni/leveldbjni/jars/leveldbjni-1.7.jar:/home/newion/.ivy2/cache/org.fusesource.leveldbjni/leveldbjni-all/bundles/leveldbjni-all-1.7.jar:/home/newion/.ivy2/cache/org.fusesource.leveldbjni/leveldbjni-linux32/jars/leveldbjni-linux32-1.5.jar:/home/newion/.ivy2/cache/org.fusesource.leveldbjni/leveldbjni-linux64/jars/leveldbjni-linux64-1.5.jar:/home/newion/.ivy2/cache/org.fusesource.leveldbjni/leveldbjni-osx/jars/leveldbjni-osx-1.5.jar:/home/newion/.ivy2/cache/org.fusesource.leveldbjni/leveldbjni-win32/jars/leveldbjni-win32-1.5.jar:/home/newion/.ivy2/cache/org.fusesource.leveldbjni/leveldbjni-win64/jars/leveldbjni-win64-1.5.jar:/home/newion/.ivy2/cache/io.spray/spray-can_2.11/bundles/spray-can_2.11-1.3.2.jar:/home/newion/.ivy2/cache/io.spray/spray-client_2.11/bundles/spray-client_2.11-1.3.2.jar:/home/newion/.ivy2/cache/io.spray/spray-http_2.11/bundles/spray-http_2.11-1.3.2.jar:/home/newion/.ivy2/cache/io.spray/spray-httpx_2.11/bundles/spray-httpx_2.11-1.3.2.jar:/home/newion/.ivy2/cache/io.spray/spray-io_2.11/bundles/spray-io_2.11-1.3.2.jar:/home/newion/.ivy2/cache/io.spray/spray-json_2.11/bundles/spray-json_2.11-1.3.1.jar:/home/newion/.ivy2/cache/io.spray/spray-util_2.11/bundles/spray-util_2.11-1.3.2.jar:/home/newion/.ivy2/cache/joda-time/joda-time/jars/joda-time-2.7.jar:/home/newion/.ivy2/cache/org.joda/joda-convert/jars/joda-convert-1.7.jar:/home/newion/.ivy2/cache/org.jvnet.mimepull/mimepull/jars/mimepull-1.9.4.jar:/home/newion/.ivy2/cache/org.parboiled/parboiled-core/bundles/parboiled-core-1.1.6.jar:/home/newion/.ivy2/cache/org.parboiled/parboiled-scala_2.11/bundles/parboiled-scala_2.11-1.1.6.jar:/home/newion/.ivy2/cache/org.scala-lang.modules/scala-xml_2.11/bundles/scala-xml_2.11-1.0.2.jar:/home/newion/.ivy2/cache/pl.newicom.dddd/akka-persistence-eventstore_2.11/jars/akka-persistence-eventstore_2.11-2.0.2-SNAPSHOT.jar:/home/newion/.ivy2/cache/com.google.guava/guava/bundles/guava-16.0.1.jar:/home/newion/.ivy2/cache/com.typesafe.akka/akka-persistence-experimental_2.11/jars/akka-persistence-experimental_2.11-2.4-SNAPSHOT.jar:/home/newion/.ivy2/cache/com.typesafe.akka/akka-slf4j_2.11/jars/akka-slf4j_2.11-2.4-SNAPSHOT.jar:/home/newion/.ivy2/cache/org.iq80.leveldb/leveldb/jars/leveldb-0.7.jar:/home/newion/.ivy2/cache/org.iq80.leveldb/leveldb-api/jars/leveldb-api-0.7.jar:/home/newion/.ivy2/cache/org.slf4j/slf4j-api/jars/slf4j-api-1.7.7.jar:/home/newion/.ivy2/cache/pl.newicom.dddd/eventstore-client_2.11/jars/eventstore-client_2.11-2.0.2-SNAPSHOT.jar:/home/newion/.ivy2/cache/com.typesafe.slick/slick_2.11/bundles/slick_2.11-2.1.0.jar:/home/newion/.ivy2/cache/com.github.dblock.waffle/waffle-jna/jars/waffle-jna-1.7.jar:/home/newion/.ivy2/cache/com.github.tminglei/slick-pg_2.11/jars/slick-pg_2.11-0.8.2.jar:/home/newion/.ivy2/cache/com.github.tminglei/slick-pg_core_2.11/jars/slick-pg_core_2.11-0.8.2.jar:/home/newion/.ivy2/cache/net.java.dev.jna/jna/jars/jna-4.1.0.jar:/home/newion/.ivy2/cache/net.java.dev.jna/jna-platform/jars/jna-platform-4.1.0.jar:/home/newion/.ivy2/cache/org.postgresql/postgresql/jars/postgresql-9.4-1200-jdbc41.jar:/home/newion/.ivy2/cache/org.scala-lang/scala-reflect/jars/scala-reflect-2.11.2.jar:/home/newion/.ivy2/cache/org.scalatest/scalatest_2.11/bundles/scalatest_2.11-2.2.4.jar:/home/newion/.ivy2/cache/com.h2database/h2/jars/h2-1.3.170.jar:/home/newion/.ivy2/cache/ch.qos.logback/logback-classic/jars/logback-classic-1.1.2.jar:/home/newion/.ivy2/cache/ch.qos.logback/logback-core/jars/logback-core-1.1.2.jar:/home/newion/.ivy2/cache/com.typesafe.akka/akka-testkit_2.11/jars/akka-testkit_2.11-2.4-SNAPSHOT.jar:/home/newion/Projects/akka-ddd/akka-ddd-test/target/scala-2.11/test-classes:/home/newion/Projects/akka-ddd/akka-ddd-test/target/scala-2.11/classes:/home/newion/Projects/akka-ddd/akka-ddd-core/target/scala-2.11/classes:/home/newion/.ivy2/cache/io.netty/netty/bundles/netty-3.8.0.Final.jar:/home/newion/.ivy2/cache/org.uncommons.maths/uncommons-maths/jars/uncommons-maths-1.2.2a.jar:/home/newion/.ivy2/cache/com.typesafe.akka/akka-cluster_2.11/jars/akka-cluster_2.11-2.4-SNAPSHOT.jar:/home/newion/.ivy2/cache/com.typesafe.akka/akka-contrib_2.11/jars/akka-contrib_2.11-2.4-SNAPSHOT.jar:/home/newion/.ivy2/cache/com.typesafe.akka/akka-remote_2.11/jars/akka-remote_2.11-2.4-SNAPSHOT.jar:/home/newion/.ivy2/cache/commons-io/commons-io/jars/commons-io-2.4.jar:/home/newion/.ivy2/cache/org.scala-sbt/test-interface/jars/test-interface-1.0.jar:/home/newion/.ivy2/cache/org.scalacheck/scalacheck_2.11/jars/scalacheck_2.11-1.11.6.jar:/home/newion/.ivy2/cache/com.typesafe.akka/akka-multi-node-testkit_2.11/jars/akka-multi-node-testkit_2.11-2.4-SNAPSHOT.jar:/opt/devel/idea-IU-139.224.1/lib/idea_rt.jar com.intellij.rt.execution.application.AppMain org.jetbrains.plugins.scala.testingSupport.scalaTest.ScalaTestRunner -s pl.newicom.dddd.view.sql.SqlViewUpdateServiceIntegrationSpec -showProgressMessages true -C org.jetbrains.plugins.scala.testingSupport.scalaTest.ScalaTestReporter
Testing started at 11:43 AM ...
[DEBUG] [03/20/2015 11:43:59.344] [ScalaTest-run] [EventStream] StandardOutLogger started
 INFO  akka.event.slf4j.Slf4jLogger - Slf4jLogger started
[DEBUG] [03/20/2015 11:43:59.819] [ScalaTest-run] [EventStream(akka://SqlViewUpdateServiceSpec)] logger log1-Slf4jLogger started
[DEBUG] [03/20/2015 11:43:59.820] [ScalaTest-run] [EventStream(akka://SqlViewUpdateServiceSpec)] Default Loggers started
10:43:59.819UTC DEBUG akka.event.EventStream - logger log1-Slf4jLogger started
10:43:59.820UTC DEBUG akka.event.EventStream - Default Loggers started10:44:00.471UTC INFO  pl.newicom.dddd.office.LocalOffice - Actor created Actor[akka://SqlViewUpdateServiceSpec/user/DummyAggregateRoot/DummyAggregateRoot-dbab46#-293628874]
10:44:00.473UTC DEBUG pl.newicom.dddd.office.LocalOffice - Forwarding EntityMessage to akka://SqlViewUpdateServiceSpec/user/DummyAggregateRoot/DummyAggregateRoot-dbab46
10:44:00.483UTC DEBUG a.p.Persistence(akka://SqlViewUpdateServiceSpec) - Create plugin: eventstore.persistence.journal akka.persistence.eventstore.journal.EventStoreJournal
10:44:00.488UTC DEBUG a.p.Persistence(akka://SqlViewUpdateServiceSpec) - Create plugin: akka.persistence.snapshot-store.local akka.persistence.snapshot.local.LocalSnapshotStore
10:44:00.551UTC DEBUG akka.io.TcpOutgoingConnection - Attempting connection to [/127.0.0.1:1113]
10:44:00.554UTC DEBUG akka.io.TcpOutgoingConnection - Connection established to [/127.0.0.1:1113]
10:44:00.595UTC INFO  eventstore.tcp.ConnectionActor - Connected to /127.0.0.1:1113
10:44:00.814UTC DEBUG p.n.d.v.s.SqlViewUpdateServiceIntegrationSpec$$anon$3$$anonfun$props$1$$anon$1 - Received: CommandMessage(CreateDummy(DummyAggregateRoot-dbab46,name,description,value),12146ceb-21d8-4e92-8d16-0331d8bd2334,Fri Mar 20 11:44:00 CET 2015)
10:44:00.876UTC DEBUG a.s.Serialization(akka://SqlViewUpdateServiceSpec) - Using serializer[pl.newicom.dddd.test.dummy.EventStoreSerializer] for message [akka.persistence.PersistentImpl]
 DEBUG s.slick.jdbc.JdbcBackend.statement - Preparing statement: select x2."ID", x2."VIEW_ID", x2."LAST_EVENT_NR" from "view_metadata" x2 where x2."VIEW_ID" = ?
10:44:00.967UTC DEBUG pl.newicom.dddd.view.ViewUpdater - Subscribed to DummyAggregateRoot, lastEventNumber = None
10:44:00.995UTC DEBUG pl.newicom.dddd.view.ViewUpdater - RECEIVED: LiveProcessingStarted
10:44:01.218UTC INFO  p.n.d.v.s.SqlViewUpdateServiceIntegrationSpec$$anon$3$$anonfun$props$1$$anon$1 - Event persisted: DummyCreated(DummyAggregateRoot-dbab46,name,description,value)
10:44:01.247UTC ERROR eventstore.StreamSubscriptionActor - eventstore.CommandNotExpectedException: Expected: StreamEventAppeared, actual: StreamEventAppeared(IndexedEvent(ResolvedEvent(EventRecord(Stream(DummyAggregateRoot-DummyAggregateRoot-dbab46),EventNumber(0),EventData(pl.newicom.dddd.test.dummy.DummyAggregateRoot$DummyCreated,e12fcef7-13dd-47eb-8900-97235b8bb795,Content(ByteString(123,34,106,115,111,110,67,108,97,..),ContentType.Binary),Content(ByteString(123,34,106,115,111,110,67,108,97,..),ContentType.Binary)),Some(2015-03-20T11:44:01.187+01:00)),EventRecord(SystemStream($ce-DummyAggregateRoot),EventNumber(0),EventData($>,44123597-eacc-f379-b45b-8957c9a049be,Content(ByteString(48,64,68,117,109,109,121,65,103,..),ContentType.Binary),Content(ByteString(123,34,36,118,34,58,34,51,58,..),ContentType.Binary)),Some(2015-03-20T11:44:01.206+01:00))),Position(59129)))
10:44:01.257UTC INFO  akka.actor.LocalActorRef - Message [akka.dispatch.sysmsg.Suspend] from Actor[akka://SqlViewUpdateServiceSpec/user/$a/$b/DummyAggregateRoot-subscription#1522803862] to Actor[akka://SqlViewUpdateServiceSpec/user/$a/$b/DummyAggregateRoot-subscription#1522803862] was not delivered. [1] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
10:44:01.260UTC ERROR akka.actor.OneForOneStrategy - Expected: StreamEventAppeared, actual: StreamEventAppeared(IndexedEvent(ResolvedEvent(EventRecord(Stream(DummyAggregateRoot-DummyAggregateRoot-dbab46),EventNumber(0),EventData(pl.newicom.dddd.test.dummy.DummyAggregateRoot$DummyCreated,e12fcef7-13dd-47eb-8900-97235b8bb795,Content(ByteString(123,34,106,115,111,110,67,108,97,..),ContentType.Binary),Content(ByteString(123,34,106,115,111,110,67,108,97,..),ContentType.Binary)),Some(2015-03-20T11:44:01.187+01:00)),EventRecord(SystemStream($ce-DummyAggregateRoot),EventNumber(0),EventData($>,44123597-eacc-f379-b45b-8957c9a049be,Content(ByteString(48,64,68,117,109,109,121,65,103,..),ContentType.Binary),Content(ByteString(123,34,36,118,34,58,34,51,58,..),ContentType.Binary)),Some(2015-03-20T11:44:01.206+01:00))),Position(59129)))
eventstore.CommandNotExpectedException: Expected: StreamEventAppeared, actual: StreamEventAppeared(IndexedEvent(ResolvedEvent(EventRecord(Stream(DummyAggregateRoot-DummyAggregateRoot-dbab46),EventNumber(0),EventData(pl.newicom.dddd.test.dummy.DummyAggregateRoot$DummyCreated,e12fcef7-13dd-47eb-8900-97235b8bb795,Content(ByteString(123,34,106,115,111,110,67,108,97,..),ContentType.Binary),Content(ByteString(123,34,106,115,111,110,67,108,97,..),ContentType.Binary)),Some(2015-03-20T11:44:01.187+01:00)),EventRecord(SystemStream($ce-DummyAggregateRoot),EventNumber(0),EventData($>,44123597-eacc-f379-b45b-8957c9a049be,Content(ByteString(48,64,68,117,109,109,121,65,103,..),ContentType.Binary),Content(ByteString(123,34,36,118,34,58,34,51,58,..),ContentType.Binary)),Some(2015-03-20T11:44:01.206+01:00))),Position(59129)))
10:44:00.876UTC DEBUG s.slick.jdbc.JdbcBackend.statement - Preparing statement: select x2."ID", x2."VIEW_ID", x2."LAST_EVENT_NR" from "view_metadata" x2 where x2."VIEW_ID" = ?
10:44:01.280UTC DEBUG pl.newicom.dddd.view.ViewUpdater - Subscribed to DummyAggregateRoot, lastEventNumber = None
 DEBUG s.slick.jdbc.JdbcBackend.statement - Preparing statement: select x2."ID", x2."VIEW_ID", x2."LAST_EVENT_NR" from "view_metadata" x2 where x2."VIEW_ID" = ?
 DEBUG s.slick.jdbc.JdbcBackend.statement - Preparing statement: select x2."ID", x2."VIEW_ID", x2."LAST_EVENT_NR" from "view_metadata" x2 where x2."VIEW_ID" = ?
 DEBUG s.slick.jdbc.JdbcBackend.statement - Preparing statement: drop table "view_metadata"
 DEBUG s.slick.jdbc.JdbcBackend.statement - Preparing statement: create table "view_metadata" ("ID" BIGINT GENERATED BY DEFAULT AS IDENTITY(START WITH 1) PRIMARY KEY,"VIEW_ID" VARCHAR NOT NULL,"LAST_EVENT_NR" BIGINT NOT NULL)
10:44:01.378UTC DEBUG akka.io.SelectionHandler - Monitored actor [Actor[akka://SqlViewUpdateServiceSpec/user/eventstore-connection/$a#100137683]] terminated
 DEBUG s.slick.jdbc.JdbcBackend.statement - Preparing statement: insert into "view_metadata" ("VIEW_ID","LAST_EVENT_NR")  values (?,?)
10:44:01.383UTC INFO  akka.actor.LocalActorRef - Message [eventstore.LiveProcessingStarted$] from Actor[akka://SqlViewUpdateServiceSpec/user/$a/$d/DummyAggregateRoot-subscription#1687751960] to Actor[akka://SqlViewUpdateServiceSpec/user/$a/$d#1251596220] was not delivered. [2] dead letters encountered. This logging can be turned off or adjusted with configuration settings 'akka.log-dead-letters' and 'akka.log-dead-letters-during-shutdown'.
10:44:01.386UTC DEBUG akka.event.EventStream - shutting down: StandardOutLogger started
[DEBUG] [03/20/2015 11:44:01.386] [SqlViewUpdateServiceSpec-akka.actor.default-dispatcher-11] [EventStream] shutting down: StandardOutLogger started
[DEBUG] [03/20/2015 11:44:01.389] [SqlViewUpdateServiceSpec-akka.actor.default-dispatcher-11] [EventStream] all default loggers stopped

Process finished with exit code 0
albertolobrano commented 9 years ago

nice work Pawel. I am using your framework to build an erp system. I built an elastic search view update and getting the same error. I will be happy to release it once done

pawelkaczor commented 9 years ago

Hi Alberto, I'm glad to hear you use akka-ddd. Feel free to contribute (elastic-search view-update would be a great add-on!), report issues or contact me if you have any questions.

pawelkaczor commented 9 years ago

EventStore JVM client has been fixed.