Polyflow task sync sometimes not working

simonhir commented 7 months ago

Very rarely it occurs that engine task changes are not correctly represented in polyflow. That means that tasks are not created or not closed.

Observations with below example

Task and process has been completed in engine
TaskCompletedEngineEvent correctly in COMAIN_EVENT_ENTRY table in engine db
Task still present in plf_task table in tasklist db

Acceptance criteria

All events are correctly represented in the tasklist

Reference

INC0380533
SCTASK0714575
INC0382149
INC0382566
INC0382560
https://git.muenchen.de/digitalisierung/digiwf-support/-/issues/442

simonhir commented 7 months ago

Problem seems to be that a older message when sorted via timestamp has a lower global_index. The task so was closed and then recreated by the assign event.

simonhir commented 7 months ago

For above mentioned incident the solution was to manually delete the task with all correlating data.

simonhir commented 7 months ago

Problem reoccurred but this time the timestamps and global_index are not in conflicting order. Seems to be not the reason for the problem.

simonhir commented 7 months ago

Reoccurred but this time the task was not created in the tasklist.

zambrovski commented 6 months ago

We need more metrics in prometheus to detect the occurencies.

darenegade commented 6 months ago

Wartet auf #1229, um den Fehler einzugrenzen

simonhir commented 6 months ago

@zambrovski im Rahmen von #1392 habe ich auf Processes-Hotfix einen Reimport angestoßen, dabei ist mir folgendes aufgefallen:

Ausgangszustand: In der Engine existieren 6 Tasks mehr als in der Tasklist (Engine: 120, Tasklist: 114)
Beim Import wird für jeden Task in der Engine (120) ein Axon Event gesendet und Empfangen, jedoch erhöht sich die Anzahl in der Tasklist nicht
Im Log der Tasklist sind keine Fehler erkennbar

Sieht für mich so aus, wie wenn die Taskliste also für manche Events nichts ändert und das an den Tasks selbst zu liegen scheint, weil ja die gleichen immer wieder ignoriert werden, so wie es aussieht. Die entsprechenden Tasks sind hier verlinkt: https://github.com/it-at-m/digiwf-core/issues/1392#issuecomment-1972878205

zambrovski commented 6 months ago

Hat sich nicht bestätigt... Verbessertes logging eingebaut und mit Polyflow 4.1.4 released. Ist eingebaut und wir schauen, was nun passiert

darenegade commented 5 months ago

Problem konnte durch einen koordinierten Lasttest nicht mehr reproduziert werden und ist auch schon länger nicht mehr aufgetreten.

Wir richten einen Alert ein auf den Processes-* und Prod. Bis das Problem wieder aufkommt, wird das Ticket erstmal geschlossen

simonhir commented 5 months ago

Aufgetreten auf Processes-Test für Instanz ecb94808-e82a-11ee-8b4a-0a580a8a27ad mit Task 9ef184d3-e82b-11ee-90eb-0a580a8a319e:

Verhalten war hier, dass die Engine in dem Moment gecrasht hat, das führte zu folgender Fehlermeldung. Wie man aus der Fehlermeldung schließen kann wurde in diesem Fall gar kein Axon-Event erzeugt.

Log

2024-03-22T10:07:38.741 ``` org.axonframework.commandhandling.NoHandlerForCommandException: No handler was subscribed for command [io.holunda.camunda.taskpool.api.task.CreateTaskCommand]. at org.axonframework.commandhandling.SimpleCommandBus.doDispatch(SimpleCommandBus.java:167) at org.axonframework.commandhandling.SimpleCommandBus.lambda$dispatch$1(SimpleCommandBus.java:131) at org.axonframework.tracing.Span.run(Span.java:101) at org.axonframework.commandhandling.SimpleCommandBus.dispatch(SimpleCommandBus.java:125) at org.axonframework.commandhandling.gateway.AbstractCommandGateway.send(AbstractCommandGateway.java:76) at org.axonframework.commandhandling.gateway.DefaultCommandGateway.send(DefaultCommandGateway.java:83) at io.holunda.polyflow.taskpool.sender.gateway.AxonCommandListGateway.sendToGateway(AxonCommandListGateway.kt:31) at io.holunda.polyflow.taskpool.sender.task.DirectTxAwareAccumulatingEngineTaskCommandSender.send(DirectTxAwareAccumulatingEngineTaskCommandSender.kt:27) at io.holunda.polyflow.taskpool.sender.task.TxAwareAccumulatingEngineTaskCommandSender$send$2.beforeCommit(TxAwareAccumulatingEngineTaskCommandSender.kt:46) at org.springframework.transaction.support.TransactionSynchronizationUtils.triggerBeforeCommit(TransactionSynchronizationUtils.java:97) at org.springframework.transaction.support.AbstractPlatformTransactionManager.triggerBeforeCommit(AbstractPlatformTransactionManager.java:916) at org.springframework.transaction.support.AbstractPlatformTransactionManager.processCommit(AbstractPlatformTransactionManager.java:727) at org.springframework.transaction.support.AbstractPlatformTransactionManager.commit(AbstractPlatformTransactionManager.java:711) at org.springframework.transaction.support.TransactionTemplate.execute(TransactionTemplate.java:152) at org.camunda.bpm.engine.spring.SpringTransactionInterceptor.execute(SpringTransactionInterceptor.java:71) at org.camunda.bpm.engine.impl.interceptor.ProcessApplicationContextInterceptor.execute(ProcessApplicationContextInterceptor.java:70) at org.camunda.bpm.engine.impl.interceptor.CommandCounterInterceptor.execute(CommandCounterInterceptor.java:35) at org.camunda.bpm.engine.impl.interceptor.LogInterceptor.execute(LogInterceptor.java:33) at org.camunda.bpm.engine.impl.interceptor.ExceptionCodeInterceptor.execute(ExceptionCodeInterceptor.java:55) at org.camunda.bpm.engine.impl.jobexecutor.ExecuteJobHelper.executeJob(ExecuteJobHelper.java:57) at org.camunda.bpm.engine.impl.jobexecutor.ExecuteJobsRunnable.executeJob(ExecuteJobsRunnable.java:110) at org.camunda.bpm.engine.impl.jobexecutor.ExecuteJobsRunnable.run(ExecuteJobsRunnable.java:71) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:840) ```

darenegade commented 5 months ago

Scheint eine Race-Condition beim Gracefull-Shutdown vorzuliegen, da der Handler für CreateTaskCommand existiert an sich, da es sonst gar nicht gehen würde

darenegade commented 5 months ago

Änderung zum Graceful-Shutdown: https://github.com/it-at-m/digiwf-core/pull/1207

simonhir commented 5 months ago

Entsprechendes Axon-Issue dazu: https://github.com/AxonFramework/AxonFramework/issues/891 Muss mal noch schauen ab welcher Version das behoben ist und ob es eigentlich schon gehen müsste

darenegade commented 5 months ago

Muss mal noch schauen ab welcher Version das behoben ist und ob es eigentlich schon gehen müsste

Hatte ich schon geprüft. Axon hat das seit 4.3 und wir nutzen 4.9.

Wo ich noch nicht sicher bin, ist ob es richtig bei uns integriert ist, sodass dies auch greift und ob das auch Polyflow richtig unterstützt.

simonhir commented 5 months ago

Aktueller Stand: Events werden immer korrekt in die DOMAIN_EVENT_ENTRY Tabelle geschrieben, aber von dort nicht an die Tasklist weitergeleitet

darenegade commented 5 months ago

https://docs.axoniq.io/reference-guide/extensions/kafka

simonhir commented 5 months ago

Debugging durch setzen des Tokens auf einen vergangen Wert um das erneute senden der Events auszulosen.

select processor_name, to_char(token) from token_entry where processor_name = 'de.muenchen.oss.digiwf.task.polyflow.kafka';

update token_entry set token = to_blob( utl_raw.cast_to_raw('{"index":1010650,"gaps":[]}')) where processor_name = 'de.muenchen.oss.digiwf.task.polyflow.kafka';
commit;

Fehlende Tasks werden immer noch nicht angelegt.

simonhir commented 5 months ago

Debugging durch setzen des Tokens auf einen vergangen Wert um das erneute senden der Events auszulosen.

select processor_name, to_char(token) from token_entry where processor_name = 'de.muenchen.oss.digiwf.task.polyflow.kafka';

update token_entry set token = to_blob( utl_raw.cast_to_raw('{"index":1010650,"gaps":[]}')) where processor_name = 'de.muenchen.oss.digiwf.task.polyflow.kafka';
commit;

Fehlende Tasks werden immer noch nicht angelegt.

zambrovski commented 5 months ago

Aktuelle Diagnose

Der global_index und timestamp sind nicht konsistent in der domain_event_entry - es tauchen Events mit einer höherem Index zeitlich "VOR" den Events mit kleineren Nummern. Das füht dazu das TEP nicht richtig die Events ans Kafka liefert, was zur Diskrepanz zwischen der Engine und tasklist führt.

Grund

Die Verwendung von JPA/Hibernate default sequence increment von 50 führt zu diesem Verhalten bei mehr als einem Knoten.

Behebung

INCREMENT BY in DOMAIN_EVENT_ENTRY_SEQ auf 1 setzen (in DB)
set property in Spring: spring.jpa.properties.hibernate.id.optimizer.pooled.preferred=none

Mehr details

Weitere Hinweise

Falls es doch nicht so klapped habe ich auch gelesen, dass es einen hibernate.id.optimizer.pooled.preferred=org.hibernate.id.enhanced.NoopOptimizer gibt... Vielleicht hilft der dann.

darenegade commented 5 months ago

Pods runterfahren
In DB:

ALTER SEQUENCE domain_event_entry_seq
INCREMENT BY 1;

Config hinzufügen: SPRING_JPA_PROPERTIES_HIBERNATE_ID_OPTIMIZER_POOLED_PREFERRED = none
Pods hochfahren

markostreich commented 5 months ago

@zambrovski @darenegade müssen domain_event_entry_seq und global_index auch noch angeglichen werden? Sie sind gerade 878 Werte auseinander gedriftet.

darenegade commented 5 months ago

Lass uns das als PN kurz besprechen. Falls du auf die Demo geschaut hast, darfst du den Werten dort nicht trauen, da ich aktuell ein paar Tests für den HotFix mache

darenegade commented 5 months ago

Änderung wurde auf Demo ausgerollt und getestet. Grundsätzlich funktioniert die Config und Tasks werden synchronisiert. Die alten Fälle lassen sich damit natürlich nicht mehr "heilen", da die Reihenfolge nicht korrigiert ist. Man kann dies aber manuell beheben und dann passt es wieder.

Hier eine Query um die Fälle herauszufinden:

SELECT count(*) FROM domain_event_entry t1 
INNER JOIN domain_event_entry t2 
ON t1.aggregate_identifier = t2.aggregate_identifier 
WHERE t1.TIME_STAMP < t2.TIME_STAMP 
AND t1.GLOBAL_INDEX > t2.GLOBAL_INDEX
AND t1.payload_type='io.holunda.camunda.taskpool.api.task.TaskCreatedEngineEvent'
AND (
    t2.payload_type='io.holunda.camunda.taskpool.api.task.TaskCompletedEngineEvent' 
    OR
    t2.payload_type='io.holunda.camunda.taskpool.api.task.TaskDeletedEngineEvent'
    )
order by t1.TIME_STAMP ASC;

Anzahl Fälle:

Prod: 1272 Proc-Test: 949 Proc-Demo: 242

darenegade commented 5 months ago

Fix ausgerollt auf Processes-*. Nun warten auf Rückmeldung, ob das Problem damit behoben...

darenegade commented 5 months ago

Ansonsten ist die Lösung noch etwas wackelig, was eine Neuinstallation oder so angeht. Da wird der INCREMENT BY wieder standardmäßig auf 50 gesetzt. Das müssten wir noch anpassen.

Siehe: https://github.com/it-at-m/digiwf-core/pull/1097

Update: Hier angepasst https://github.com/it-at-m/digiwf-core/pull/1527

darenegade commented 5 months ago

Falls es doch nicht so klapped habe ich auch gelesen, dass es einen hibernate.id.optimizer.pooled.preferred=org.hibernate.id.enhanced.NoopOptimizer gibt... Vielleicht hilft der dann.

none sollte eigentlich den NoopOptimizer setzen, womit diese Config gleichwertig wäre https://docs.jboss.org/hibernate/orm/5.5/javadocs/org/hibernate/id/enhanced/StandardOptimizerDescriptor.html#NONE

darenegade commented 5 months ago

@simonhir Wir müssen das Monitoring auch unbedingt wieder aktivieren. Aktuell kann man auf keiner Umgebung die Daten für die Engine sehen

simonhir commented 4 months ago

Unterschied der mir auf dev im Gegensatz zu processestraining aufgefallen ist:

dev: gleicher User für beide Schemata
processestraining: unterschiedlicher User je Schema

Hab mit REQ0682591 eine Anpassung von dev auf den gleichen Zustand beantragt um das auszuschließen. Denke aber es könnte schon daran liegen.

simonhir commented 4 months ago

Aufsplitten zu zwei separaten PostgreSQL-Usern für Engine und Tasklist hat das Problem wie oben vermutet behoben.

simonhir commented 4 months ago

Nach erneuten Fehlern merke: In Zukunft Schema neu anlegen lassen anstatt auf neuen User zu übertragen

Fehler danach behoben

it-at-m / digiwf-core