Bug: OutOfMemoryError beim Löschen von Submissions im Status ACCEPTED

added type::Bug + 1 deleted label

assigned to @Michael_Miera

added workflow::Ready label

changed milestone to %Q-1 (Y-2023)

added workflow::In Progress label and removed workflow::Ready label

added workflow::Peer Review label and removed workflow::In Progress label

added workflow::PO Review label and removed workflow::Peer Review label

changed the description

added workflow::Ready for DEV deployment label and removed workflow::PO Review label

added workflow::Ready for TEST deployment label and removed workflow::Ready for DEV deployment label

added 1 deleted label and removed workflow::Ready for TEST deployment label

Das Problem scheint nicht behoben zu sein. Aus dem fc-dev-service Log von 2023-03-29T01:40:55.359Z:

java.lang.reflect.InvocationTargetException: null
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at org.jobrunr.server.runner.AbstractBackgroundJobRunner.invokeJobMethod(AbstractBackgroundJobRunner.java:65)
	at org.jobrunr.server.runner.AbstractBackgroundJobRunner.run(AbstractBackgroundJobRunner.java:39)
	at org.jobrunr.server.runner.AbstractBackgroundJobRunner.run(AbstractBackgroundJobRunner.java:21)
	at org.jobrunr.server.BackgroundJobPerformer.runActualJob(BackgroundJobPerformer.java:83)
	at org.jobrunr.server.BackgroundJobPerformer.run(BackgroundJobPerformer.java:43)
	at java.base/java.util.concurrent.Executors.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor.run(ScheduledThreadPoolExecutor.java:304)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: java.lang.OutOfMemoryError: Java heap space
	at java.base/java.util.Arrays.copyOf(Arrays.java:3745)
	at java.base/java.io.ByteArrayOutputStream.grow(ByteArrayOutputStream.java:120)
	at java.base/java.io.ByteArrayOutputStream.ensureCapacity(ByteArrayOutputStream.java:95)
	at java.base/java.io.ByteArrayOutputStream.write(ByteArrayOutputStream.java:156)
	at org.hibernate.type.descriptor.java.DataHelper.extractBytes(DataHelper.java:170)
	at org.hibernate.type.descriptor.java.PrimitiveByteArrayTypeDescriptor.wrap(PrimitiveByteArrayTypeDescriptor.java:120)
	at org.hibernate.type.descriptor.java.PrimitiveByteArrayTypeDescriptor.wrap(PrimitiveByteArrayTypeDescriptor.java:26)
	at org.hibernate.type.descriptor.sql.BlobTypeDescriptor.doExtract(BlobTypeDescriptor.java:48)
	at org.hibernate.type.descriptor.sql.BasicExtractor.extract(BasicExtractor.java:47)
	at org.hibernate.type.AbstractStandardBasicType.nullSafeGet(AbstractStandardBasicType.java:257)
	at org.hibernate.type.AbstractStandardBasicType.nullSafeGet(AbstractStandardBasicType.java:253)
	at org.hibernate.type.AbstractStandardBasicType.nullSafeGet(AbstractStandardBasicType.java:243)
	at org.hibernate.type.AbstractStandardBasicType.hydrate(AbstractStandardBasicType.java:329)
	at org.hibernate.persister.entity.AbstractEntityPersister.hydrate(AbstractEntityPersister.java:3214)
	at org.hibernate.persister.entity.Loadable.hydrate(Loadable.java:94)
	at org.hibernate.loader.plan.exec.process.internal.EntityReferenceInitializerImpl.loadFromResultSet(EntityReferenceInitializerImpl.java:342)
	at org.hibernate.loader.plan.exec.process.internal.EntityReferenceInitializerImpl.hydrateEntityState(EntityReferenceInitializerImpl.java:269)
	at org.hibernate.loader.plan.exec.process.internal.AbstractRowReader.readRow(AbstractRowReader.java:80)
	at org.hibernate.loader.plan.exec.process.internal.ResultSetProcessorImpl.extractRows(ResultSetProcessorImpl.java:157)
	at org.hibernate.loader.plan.exec.process.internal.ResultSetProcessorImpl.extractResults(ResultSetProcessorImpl.java:94)
	at org.hibernate.loader.plan.exec.internal.AbstractLoadPlanBasedLoader.executeLoad(AbstractLoadPlanBasedLoader.java:105)
	at org.hibernate.loader.collection.plan.AbstractLoadPlanBasedCollectionInitializer.initialize(AbstractLoadPlanBasedCollectionInitializer.java:87)
	at org.hibernate.persister.collection.AbstractCollectionPersister.initialize(AbstractCollectionPersister.java:705)
	at org.hibernate.event.internal.DefaultInitializeCollectionEventListener.onInitializeCollection(DefaultInitializeCollectionEventListener.java:76)
	at org.hibernate.internal.SessionImpl21143Lambda/0x0000000840cb5840.accept(Unknown Source)
	at org.hibernate.event.service.internal.EventListenerGroupImpl.fireEventOnEachListener(EventListenerGroupImpl.java:107)
	at org.hibernate.internal.SessionImpl.initializeCollection(SessionImpl.java:2208)
	at org.hibernate.collection.internal.AbstractPersistentCollection.doWork(AbstractPersistentCollection.java:595)
	at org.hibernate.collection.internal.AbstractPersistentCollection.withTemporarySessionIfNeeded(AbstractPersistentCollection.java:264)
	at org.hibernate.collection.internal.AbstractPersistentCollection.initialize(AbstractPersistentCollection.java:591)
	at org.hibernate.collection.internal.PersistentSet.clear(PersistentSet.java:316)
	at de.fiep.zustelldienst.model.submission.Submission.deleteAttachments(Submission.java:164)

Blöd. versucht ihr es noch heute / morgen es auf Test nachzuziehen um es Fr. auf Refz und Di auf Prod zu schieben, oder ist die Taktung verworfen?

Gibt bitte ein kurzes Update auch an @Maik_Boettner. Er geht in die Kommunikation - sollte aus meiner Sicht spätestens diesen Donnerstag rausgehen.

Ich würde heute den entsprechenden Merge-Request stellen. Damit würde es morgen auf dev/test landen (@Maik_Boettner). Genaue Fehleranalyse bzw. Erklärung warum es zu diesem Problem kam folgt dann wahrscheinlich morgen Vormittag.

added workflow::In Progress label and removed 1 deleted label

Es scheint so zu sein, dass beim Leeren der Collection (attachments.clear()) von Seiten Hibernates zuerst die Collection eingelesen wird. Hierfür gibt es wohl mehrere Gründe, alles in allem aber ein "normales" Verhalten.
Siehe Kommentare ab https://github.com/smallrye/smallrye-graphql/issues/95#issuecomment-607068745 bzgl. Typenerkennung und https://thorben-janssen.com/hibernate-tip-fastest-option-delete-100-records/ bzgl. generellen Verhaltens beim Löschen.

Basierend auf dem folgenden Logauszug lässt sich erkennen, dass Hibernate beim Löschen zuerst alles einliest, weiteren Code ausführt und erst irgendwann später die Attachments echt löscht. Das Einlesen findet aber bereits direkt beim Ausführen von .clear() aus.

Hibernate: select attachment0_.fk_submission as fk_submi5_0_0_, attachment0_.id as id1_0_0_, attachment0_.id as id1_0_1_, attachment0_.attachment_id as attachme2_0_1_, attachment0_.content as content3_0_1_, attachment0_.content_size as content_4_0_1_, attachment0_.fk_submission as fk_submi5_0_1_ from attachment attachment0_ where attachment0_.fk_submission=?

Hibernate: select announceda0_.submission_id as submissi1_11_0_, announceda0_.announced_attachment as announce2_11_0_ from submission_announced_attachments announceda0_ where announceda0_.submission_id=?

Hibernate: select nextval ('event_log_id_seq')
Hibernate: insert into event_log (event, fk_submission, token, token_id, id) values (?, ?, ?, ?, ?)
Hibernate: update submission set callback_id=?, case_id=?, current_status=?, destination_id=?, encrypted_data=?, encrypted_metadata=?, service_type_id=?, state_changed_at=? where id=?
Hibernate: update event_log set event=?, fk_submission=?, token=?, token_id=? where id=?

Hibernate: delete from submission_announced_attachments where submission_id=?
Hibernate: delete from attachment where id=?
Hibernate: delete from attachment where id=?

Neue Version des Zustelldienstes wurde auf dev deployed. Zusätzlich wurde auf Anraten von @Andreas_Huber der Cron Job für den Löschvorgang vorverlegt. Dieser sollte heute um 15:01 Uhr laufen.

Wenn alles hinhaut, kann anschließend auf test deployed werden.

Leider lief der Cron nicht oder hatte keinen Erfolg:

zustelldienst=> SELECT current_status, count(distinct id) FROM submission GROUP BY current_status;
 current_status | count 
----------------+-------
 ACCEPTED       |  9712
 DELETED        | 13174
 INCOMPLETE     |     1
 SUBMITTED      |     7
(4 rows)

Laut Datenbank wird der Job morgen früh um 3:40 (1:40 UTC) ausgeführt.

zustelldienst=> select id, state, scheduledat, recurringjobid from jobrunr_jobs where recurringjobid='de.fiep.zustelldienst.scheduling.DeleteAcceptedSubmissionsService' and state != 'FAILED';
                  id                  |   state   |        scheduledat         |                          recurringjobid                           
--------------------------------------+-----------+----------------------------+-------------------------------------------------------------------
 88ea2b18-0af9-43fd-8126-997cecb9893f | SCHEDULED | 2023-03-31 01:40:46.508178 | de.fiep.zustelldienst.scheduling.DeleteAcceptedSubmissionsService
(1 row)

added 1 deleted label and removed workflow::In Progress label

marked the checklist item Submissions werden einzeln verarbeitet as completed

marked the checklist item Andere Löschjobs wurden ebenfalls überprüft as completed

marked the checklist item Andere Repositories wurden ebenfalls auf Batch-Verarbeitung überprüft as completed

closed

removed 1 deleted label

mentioned in issue #1097 (closed)

Bug: OutOfMemoryError beim Löschen von Submissions im Status ACCEPTED

Zusammenfassung

Schritte zum Reproduzieren

Wie verhält sich der aktuelle Fehler?

Was ist das erwartete richtige Verhalten?

Relevante Protokolle/Screenshots/Anfragen

Akzeptanzkriterien zur Fehlerbehebung

Designs

Child items ...

Activity