WriteModel database bug results in known GUIDs being missed

Question

WriteModel database bug results in known GUIDs being missed

Closed this issue 3 years ago · 0 comments

The WriteModel is expected to save GUIDs from PersistedEvents to the database model GUID. When Commands are received, the database is searched for the given guid, and known entities can be tagged, not created (i.e. PERSON_TAGGED event vs PERSON_ADDED). To address eventual consistency issues, the WriteModel also implements a short term memory -- essentially a dict where on addition, entries are given a TTL, and when that expires they are automatically deleted. The short term memory is checked before the database is queried, to cover the time between emitting an event and receiving it back on the persisted events stream.

The following log shows that a Person entity with the GUID 'f222cb99-01e9-4963-a620-63b5c1a8e27f' was added to the GUID table of the database (first 12 lines), and the last several lines show the SQL that fails to find the same entity. This results in the person being given a PERSON_ADDED event, and causes bugs in the ReadModel, where GUIDs are expected to be unique.

DEBUG:pybroker.broker_base:Handling a message with routing key event.replay.writemodel
INFO:root:EventHandler: processing event {'event_id': 7, 'type': 'PERSON_ADDED', 'transaction_guid': '7166d62b-4d3b-46f8-a67a-9f6e7449f61d', 'app_version': '0.1.0', 'timestamp': '2021-05-28T19:35:48.234Z', 'user': 'test-user', 'payload': {'citation_guid': '45861ebe-a260-4fa5-becf-2dc851d50946', 'person_guid': 'f222cb99-01e9-4963-a620-63b5c1a8e27f', 'person_name': 'Bach', 'citation_start': 0, 'citation_end': 5}}
2021-06-02 19:32:15,547 INFO sqlalchemy.engine.Engine BEGIN (implicit)
INFO:sqlalchemy.engine.Engine:BEGIN (implicit)
2021-06-02 19:32:15,548 INFO sqlalchemy.engine.Engine INSERT INTO guids (value, type) VALUES (?, ?)
2021-06-02 19:32:15,548 INFO sqlalchemy.engine.Engine [cached since 0.05751s ago] ('PERSON', 'f222cb99-01e9-4963-a620-63b5c1a8e27f')
INFO:sqlalchemy.engine.Engine:INSERT INTO guids (value, type) VALUES (?, ?)
INFO:sqlalchemy.engine.Engine:[cached since 0.05751s ago] ('PERSON', 'f222cb99-01e9-4963-a620-63b5c1a8e27f')
INFO:sqlalchemy.engine.Engine:COMMIT
2021-06-02 19:32:15,549 INFO sqlalchemy.engine.Engine COMMIT
DEBUG:pybroker.broker_base:Handling a message with routing key event.replay.writemodel
INFO:root:EventHandler: processing event {'event_id': 8, 'type': 'TIME_ADDED', 'transaction_guid': '7166d62b-4d3b-46f8-a67a-9f6e7449f61d', 'app_version': '0.1.0', 'timestamp': '2021-05-28T19:35:48.234Z', 'user': 'test-user', 'payload': {'citation_guid': '45861ebe-a260-4fa5-becf-2dc851d50946', 'time_guid': '04388c22-71e0-4e56-8f3e-d960144e0cec', 'time_name': '1714', 'citation_start': 52, 'citation_end': 57}}
INFO:sqlalchemy.engine.Engine:BEGIN (implicit)
INFO:sqlalchemy.engine.Engine:INSERT INTO guids (value, type) VALUES (?, ?)
INFO:sqlalchemy.engine.Engine:[cached since 0.06059s ago] ('TIME', '04388c22-71e0-4e56-8f3e-d960144e0cec')
INFO:sqlalchemy.engine.Engine:COMMIT
2021-06-02 19:32:15,551 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2021-06-02 19:32:15,551 INFO sqlalchemy.engine.Engine INSERT INTO guids (value, type) VALUES (?, ?)
2021-06-02 19:32:15,551 INFO sqlalchemy.engine.Engine [cached since 0.06059s ago] ('TIME', '04388c22-71e0-4e56-8f3e-d960144e0cec')
2021-06-02 19:32:15,552 INFO sqlalchemy.engine.Engine COMMIT
DEBUG:pybroker.broker_base:Handling a message with routing key event.replay.writemodel
INFO:root:EventHandler: processing event {'event_id': 9, 'type': 'PLACE_ADDED', 'transaction_guid': '7166d62b-4d3b-46f8-a67a-9f6e7449f61d', 'app_version': '0.1.0', 'timestamp': '2021-05-28T19:35:48.234Z', 'user': 'test-user', 'payload': {'citation_guid': '45861ebe-a260-4fa5-becf-2dc851d50946', 'place_guid': '203f9347-1967-43f2-bf55-94463b0f816e', 'place_name': 'Leipzig', 'citation_start': 225, 'citation_end': 234, 'longitude': 10.3147, 'latitude': 50.9796, 'geoshape': None}}
2021-06-02 19:32:15,553 INFO sqlalchemy.engine.Engine BEGIN (implicit)
2021-06-02 19:32:15,554 INFO sqlalchemy.engine.Engine INSERT INTO guids (value, type) VALUES (?, ?)
INFO:sqlalchemy.engine.Engine:BEGIN (implicit)
INFO:sqlalchemy.engine.Engine:INSERT INTO guids (value, type) VALUES (?, ?)
INFO:sqlalchemy.engine.Engine:[cached since 0.06294s ago] ('PLACE', '203f9347-1967-43f2-bf55-94463b0f816e')
INFO:sqlalchemy.engine.Engine:COMMIT
2021-06-02 19:32:15,554 INFO sqlalchemy.engine.Engine [cached since 0.06294s ago] ('PLACE', '203f9347-1967-43f2-bf55-94463b0f816e')
2021-06-02 19:32:15,554 INFO sqlalchemy.engine.Engine COMMIT
DEBUG:pybroker.broker_base:Handling a message with routing key event.replay.writemodel
INFO:root:EventHandler: processing event {'event_id': 10, 'type': 'META_ADDED', 'transaction_guid': '7166d62b-4d3b-46f8-a67a-9f6e7449f61d', 'app_version': '0.1.0', 'timestamp': '2021-05-28T19:35:48.234Z', 'user': 'test-user', 'payload': {'citation_guid': '45861ebe-a260-4fa5-becf-2dc851d50946', 'meta_guid': '39a0078a-9aa1-4490-9b55-b55d7a7ef248', 'author': 'Multiple', 'publisher': 'Wikipedia', 'title': 'Johann Sebastian Bach'}}
2021-06-02 19:32:15,555 INFO sqlalchemy.engine.Engine BEGIN (implicit)
INFO:sqlalchemy.engine.Engine:BEGIN (implicit)
2021-06-02 19:32:15,555 INFO sqlalchemy.engine.Engine INSERT INTO guids (value, type) VALUES (?, ?)
INFO:sqlalchemy.engine.Engine:INSERT INTO guids (value, type) VALUES (?, ?)
2021-06-02 19:32:15,556 INFO sqlalchemy.engine.Engine [cached since 0.06464s ago] ('META', '39a0078a-9aa1-4490-9b55-b55d7a7ef248')
INFO:sqlalchemy.engine.Engine:[cached since 0.06464s ago] ('META', '39a0078a-9aa1-4490-9b55-b55d7a7ef248')
2021-06-02 19:32:15,556 INFO sqlalchemy.engine.Engine COMMIT
INFO:sqlalchemy.engine.Engine:COMMIT
DEBUG:pybroker.broker_base:Handling a message with routing key event.replay.writemodel
DEBUG:app.broker:Ready to process events received while processing history replay
INFO:app.broker:Finished history replay
DEBUG:pybroker.broker_base:Handling a message with routing key command.writemodel
DEBUG:app.state_manager.command_handler:handling command {'type': 'PUBLISH_NEW_CITATION', 'app_version': '0.1.0', 'timestamp': '2021-06-02T21:49:13.117Z', 'user': 'test-user', 'payload': {'text': 'The date of Johann Sebastian’s birth, 21 March 1685, was carefully recorded by Walther in his Lexicon, by Sebastian himself in the family genealogy, and by his son as the co-author of the obituary. It is supported by the date of baptism (23 March; these dates are old-style) in the register of St Georg.', 'tags': [{'type': 'PERSON', 'start_char': 12, 'stop_char': 28, 'GUID': 'f222cb99-01e9-4963-a620-63b5c1a8e27f', 'name': 'Johann Sebastian'}, {'type': 'TIME', 'start_char': 38, 'stop_char': 51, 'GUID': '8cf96bfa-a472-4eec-a1f8-33fd20432e2b', 'name': '1685|1|3|21'}], 'meta': {'title': 'Bach, Johann Sebastian', 'author': 'Chistoph Wolf and Walter Emery', 'publisher': 'Grove Music Online', 'GUID': '2163aae3-892c-4394-ae4d-ee61f5dc315f'}, 'GUID': '360e76b0-3532-4c1a-a2d4-d04778e9a146'}}
INFO:app.state_manager.command_handler:CommandHandler: received a new citation: {'type': 'PUBLISH_NEW_CITATION', 'app_version': '0.1.0', 'timestamp': '2021-06-02T21:49:13.117Z', 'user': 'test-user', 'payload': {'text': 'The date of Johann Sebastian’s birth, 21 March 1685, was carefully recorded by Walther in his Lexicon, by Sebastian himself in the family genealogy, and by his son as the co-author of the obituary. It is supported by the date of baptism (23 March; these dates are old-style) in the register of St Georg.', 'tags': [{'type': 'PERSON', 'start_char': 12, 'stop_char': 28, 'GUID': 'f222cb99-01e9-4963-a620-63b5c1a8e27f', 'name': 'Johann Sebastian'}, {'type': 'TIME', 'start_char': 38, 'stop_char': 51, 'GUID': '8cf96bfa-a472-4eec-a1f8-33fd20432e2b', 'name': '1685|1|3|21'}], 'meta': {'title': 'Bach, Johann Sebastian', 'author': 'Chistoph Wolf and Walter Emery', 'publisher': 'Grove Music Online', 'GUID': '2163aae3-892c-4394-ae4d-ee61f5dc315f'}, 'GUID': '360e76b0-3532-4c1a-a2d4-d04778e9a146'}}
DEBUG:app.state_manager.event_composer:Created new logger for transaction 01eea652-bb15-4fe9-b5fc-69ad799308ff by user test-user
INFO:root:TextHasher: preparing to hash The date of Johann Sebastian’s birth, 21 March 1685, was carefully recorded by Walther in his Lexicon, by Sebastian himself in the family genealogy, and by his son as the co-author of the obituary. It is supported by the date of baptism (23 March; these dates are old-style) in the register of St Georg.
DEBUG:root:TextHasher: processed text is (thedateofjohannsebastian’sbirth21march1685wascarefullyrecordedbywaltherinhislexiconbysebastianhimselfinthefamilygenealogyandbyhissonasthecoauthoroftheobituaryitissupportedbythedateofbaptism23marchthesedatesareoldstyleintheregisterofstgeorg)
DEBUG:app.state_manager.command_handler:Text hash is 1d724760ec7c0ef3f1be16bb7f4ea7e355899f43b8ac1abcb27d79843784d8f5
2021-06-02 21:49:13,133 INFO sqlalchemy.engine.Engine BEGIN (implicit)
INFO:sqlalchemy.engine.Engine:BEGIN (implicit)
2021-06-02 21:49:13,137 INFO sqlalchemy.engine.Engine SELECT citation_hashes.id, citation_hashes.hash, citation_hashes."GUID" 
FROM citation_hashes 
WHERE citation_hashes.hash = ?
INFO:sqlalchemy.engine.Engine:SELECT citation_hashes.id, citation_hashes.hash, citation_hashes."GUID" 
FROM citation_hashes 
WHERE citation_hashes.hash = ?
INFO:sqlalchemy.engine.Engine:[generated in 0.00022s] ('1d724760ec7c0ef3f1be16bb7f4ea7e355899f43b8ac1abcb27d79843784d8f5',)
2021-06-02 21:49:13,137 INFO sqlalchemy.engine.Engine [generated in 0.00022s] ('1d724760ec7c0ef3f1be16bb7f4ea7e355899f43b8ac1abcb27d79843784d8f5',)
DEBUG:app.state_manager.database:Database: searching for citation and found None
INFO:sqlalchemy.engine.Engine:ROLLBACK
2021-06-02 21:49:13,138 INFO sqlalchemy.engine.Engine ROLLBACK
2021-06-02 21:49:13,138 INFO sqlalchemy.engine.Engine BEGIN (implicit)
INFO:sqlalchemy.engine.Engine:BEGIN (implicit)
INFO:sqlalchemy.engine.Engine:SELECT guids.id, guids.value, guids.type 
FROM guids 
WHERE guids.value = ?
2021-06-02 21:49:13,139 INFO sqlalchemy.engine.Engine SELECT guids.id, guids.value, guids.type 
FROM guids 
WHERE guids.value = ?
2021-06-02 21:49:13,139 INFO sqlalchemy.engine.Engine [generated in 0.00012s] ('360e76b0-3532-4c1a-a2d4-d04778e9a146',)
INFO:sqlalchemy.engine.Engine:[generated in 0.00012s] ('360e76b0-3532-4c1a-a2d4-d04778e9a146',)
DEBUG:app.state_manager.database:Database: searching for GUID and found None
2021-06-02 21:49:13,139 INFO sqlalchemy.engine.Engine ROLLBACK
INFO:sqlalchemy.engine.Engine:ROLLBACK
2021-06-02 21:49:13,140 INFO sqlalchemy.engine.Engine BEGIN (implicit)
INFO:sqlalchemy.engine.Engine:BEGIN (implicit)
2021-06-02 21:49:13,140 INFO sqlalchemy.engine.Engine SELECT guids.id, guids.value, guids.type 
FROM guids 
WHERE guids.value = ?
2021-06-02 21:49:13,140 INFO sqlalchemy.engine.Engine [cached since 0.001319s ago] ('f222cb99-01e9-4963-a620-63b5c1a8e27f',)
INFO:sqlalchemy.engine.Engine:SELECT guids.id, guids.value, guids.type 
FROM guids 
WHERE guids.value = ?
INFO:sqlalchemy.engine.Engine:[cached since 0.001319s ago] ('f222cb99-01e9-4963-a620-63b5c1a8e27f',)
DEBUG:app.state_manager.database:Database: searching for GUID and found None