[EPIC] Cleanup EZID queues

[jsjiang]

We run the proc-cleanup-async-queues.py script to delete successfully processed or not applicable identifiers from the binder, crossref, datacite and search queues and from the RefIdentifier table. The script filters records by the queue status (SUCCESS or IGNORED) and the update timestamps (updated in the past week). We started to run the proc-cleanup-async-queues.py script as a background job some time in 2023 (mostly likely June 29, 2023). There are some data issues with these queues:

1. There might be a status definition change with the June 29 2023 deployment:

   • the successful status changed from "S" to "O"
   • the earliest Datacite queue record with status="O" has a timestamp "2023-06-29 05:08:25" (Thursday 5am) and seq=7993833
   • there are over 7.9m records in the DataCite that were created before the seq=7993833 record; the majority has status='S' and a small group (1550 records) has status='F'; no records were logged with other status.
   • the status change from "S" to "O" applied to the searchindex queue and binder queue as well; the latest searchindex queue record with status="S" has a timestamp "2023-06-29 05:03:43" and seq=9337226; the earliest record with status="O" has a timestamp "2023-06-29 05:08:20" and seq=9337227;
   • If status='S' was used to indicate successfully processed, then those records should be deleted from the queue

2. The proc-cleanup-async-queues might have missed records with SUCCESS and IGNORED status in its processing window (now - 2 weeks)

   • In the DataCite queue there are over 4m records with success or ignore status that were ignored by proc-cleanup-async-queues job. These records should have been deleted when they had gone into the "past week" window.
   • The QuerySet is filtered by time range and batch size which is 100. When there are more than 100 records in the time range, then some records will be missed.

3. We stopped the proc-binder queue on Aug 12, 2024. However we have not stopped putting records to the ezidapp_binderqueue table. There are over 560K records with UNSUBMITTED = "U" status in the binder queue since then (seq > 14941881). All binder queue records (over 12M) can be deleted.

The changing point for the datacite queue is seq=7993833:

 select *, from_unixtime(enqueueTime), from_unixtime(submitTime) from ezidapp_datacitequeue 
 where seq between 7993833-1000 and 7993833+1000;

Records that had passed the "past week" window but had not been deleted by proc-cleanup-async-queues:

select *, from_unixtime(enqueueTime), from_unixtime(submitTime) from ezidapp_datacitequeue 
 where from_unixtime(enqueueTime) > '2023-06-28'
 and from_unixtime(enqueueTime) <  '2024-08-10'
 and status in ('O', 'I');

QuerySet with time range and batch size filters that contributed to neglected records

refIdsQS = self.refIdentifier.objects.filter(
                updateTime__lte=currentTime,
                updateTime__gte=currentTime - timeDelta
            ).order_by("-pk")[: django.conf.settings.DAEMONS_MAX_BATCH_SIZE]

EZID-PRD Queue status on 2024-10-14 reported by running the diag-queue-stats command:

{
  "download": {},
  "binder": {
    "F": 6,
    "O": 4015090,
    "S": 7993776,
    "U": 669913
  },
  "datacite": {
    "F": 1565,
    "O": 5192961,
    "S": 7992232
  },
  "crossref": {
    "F": 3863,
    "I": 13155480,
    "O": 16926,
    "W": 76
  },
  "searchindexer": {
    "F": 54,
    "O": 5291658,
    "S": 9337175
  }
}

[adambuttrick]

Part of https://github.com/CDLUC3/ezid/issues/707

[jsjiang]

Related tickets: #394 https://github.com/CDLUC3/ezid/issues/371

[jsjiang]

Queue data cleanup

Queues:

• BinderQueue - ezidapp_binderqueue
• CrossrefQueue - ezidapp_crossrefqueue
• DataciteQueue - ezidapp_datacitequeue
• SearchIndexerQueue - ezidapp_searchindexqueue

Associated datasets:

• associated identifier is the ezidapp_refIdentifier table - delete the identifier from the refIdentifer table once the identifier has been deleted from the above queues

Notes:

• The identifiers in the queues will be selected by a date range on the updatetime
• Deleting identifier from the RefIndetifier table may trigger error if the identifier was updated outside of the selected date range - this is expected as this identifier is still associated to one or more later transactions.

Procedures:

• Modify the proc-cleanup-async-queues.py script or develop a new one that can select identifiers by a specified data range (see related ticket #727 )
• Test the script:
  • only records in the specified date range are selected for processing
  • only successfully processed (Status="O") or not applicable identifiers (Status="I") are deleted from the crossref, datacite and search index queues and from the RefIdentifier table.
• Develop a rollback and recovery plan
• Stop EZID services (front end and background jobs)
• Backup the 4 queues and RefIdentifier tables. Here are the options:
  • dump the database tables to files using the MySQL dump command
  • copy the queue tables into the ezid database - make sure not to retain the foreign key restrictions otherwise deleting the referenced identifier from the RefIdentifier table will fail with "protected foreign keys" error.
• Cleanup the binder queue - delete all records from the ezidapp_binderqueue table. #726
  • the binder queue contains unsubmitted datasets in status "U" - these records were created in between stopping the binder queue job (without code change) and stopping putting identifiers to the binder queue (with code change)
• Cleanup DataCite queue records created before the seq=7993833 record with status='S' #725
  • change the status to 'O' so the identifiers can be picked up by the async queue cleanup job
• Cleanup SearchIndex queue records created before seq = 9337227, #769
• Cleanup Crossref queue: no record records to cleanup - no returns when enqueuetime <1688040600 which is '2023-06-29 05:10:00' and status='S';
• Start the async queue cleanup job with a defined date range; repeat with different date ranges until all identifiers outside of the to-be-kept window are processed
• Recover identifiers following the rollback and recovery plan if needed

Exception occured while processing identifier 'ark:/99999/fk4km0qb78' for 'refId' table
   ERROR ezidapp.management.commands.proc-cleanup-async-queues_v2 7961173056: ("Cannot delete some instances of model 'RefIdentifier' because they are referenced through protected foreign keys: 'BinderQueue.refIdentifier'.", {<BinderQueue: BinderQueue(id=1, refId=ark:/99999/fk4km0qb78, op=CREATE, status="Awaiting submission", owner="admin (admin)", group="f51340b091 ()")>})

[jsjiang]

Implementation procedure:

• disable Nagios alerts: ezid, async-cleanup, and uc3-ezid-ui-search-prd_7x16
• stop ezid services: ezid, async-cleanup
• run the python manage.py diag-queus-stats command to get queue stats
• run the ezid-ops-scripts/scripts/dump-queue-tables_ops.sh script to backup queue tables (use the eziddba account)
• run the ezid-ops-scripts/scripts/723_delete_binder_queue.sql query to delete all records from the binder queue - requires the ezidrw account and password
• run the ezid-ops-scripts/scripts/723_update_queue_status.sql query to update the datacite and searchindexer records status from "S" to "O" for records that were created before UNIX_TIMESTAMP('2023-06-29 05:10:00')=1688040600
• rerun the python manage.py diag-queus-stats command to get queue stats
• compare the queue stats with the ones got before running updates
• resume ezid services: ezid, async-cleanup
• resume Nagios alerts: ezid, async-cleanup, and uc3-ezid-ui-search-prd_7x16

[jsjiang]

Test on ezid-stg (script v0.0.8rc1):

• diag-queus-stats before batch update
• dump database tables to file
  • updated script as mysqldump on ezid-stg is a MariaDB version that does not support the --set-gtid-purged option
  • saved dump files on ezid-stg under /ezid/tmp/ezid_sql_dump_files/stg-20241021
• Update queue status - finished in about one mintute
• delete Binder queue - on hold - finished (10/23)
• diag-queus-stats before batch update

Batch update:

mysql -h rds-uc3-ezid1-stg.cmcguhglinoa.us-west-2.rds.amazonaws.com -u ezidrw ezid -p < 723_update_queue_status.sql 

Batch delete:

ezid@uc3-ezidui-stg01:15:52:54:~/ezid-ops-scripts/scripts/sql_scripts$ mysql -h rds-uc3-ezid1-stg.cmcguhglinoa.us-west-2.rds.amazonaws.com -u ezidrw ezid -p < 723_delete_binder_queue.sql 

diag-queus-stats before batch update:

{
  "download": {},
  "binder": {
    "F": 1,
    "O": 44111,
    "S": 137359,
    "U": 530
  },
  "datacite": {
    "F": 19769,
    "O": 47132,
    "S": 128571
  },
  "crossref": {
    "F": 568,
    "I": 181521,
    "O": 2439,
    "W": 6
  },
  "searchindexer": {
    "F": 103,
    "O": 47401,
    "S": 752336
  }
}

diag-queus-stats after batch update:

{
  "download": {},
  "binder": {
    "F": 1,
    "O": 44111,
    "S": 137359,
    "U": 530
  },
  "datacite": {
    "F": 19769,
    "O": 175703
  },
  "crossref": {
    "F": 568,
    "I": 181521,
    "O": 2439,
    "W": 6
  },
  "searchindexer": {
    "F": 103,
    "O": 799737
  }
}

diag-queus-stats after batch delete binder records:

{
  "download": {},
  "binder": {},
  "datacite": {
    "F": 19769,
    "O": 175722
  },
  "crossref": {
    "F": 572,
    "I": 181536,
    "O": 2441,
    "W": 6
  },
  "searchindexer": {
    "F": 103,
    "O": 799756
  }
}

Dump files:

-rw-r--r--. 1 ezid ezid 10626904 Oct 21 14:18 ezidapp_binderqueue_table_dump_20241021_141823.sql
-rw-r--r--. 1 ezid ezid  9851380 Oct 21 14:18 ezidapp_crossrefqueue_table_dump_20241021_141823.sql
-rw-r--r--. 1 ezid ezid 11784727 Oct 21 14:18 ezidapp_datacitequeue_table_dump_20241021_141823.sql
-rw-r--r--. 1 ezid ezid 47093377 Oct 21 14:18 ezidapp_searchindexerqueue_table_dump_20241021_141823.sql

[jsjiang]

Production implementation:

• Date/time: 2024-10-24, 5-6am
• Started: 5am
• restored services: 6:15am

Binder queue

• total count: 12678785
• size: 920MB
• auto_increment: 15,686,114

Crossref queue:

• total count: 13351239
• size: 605MB
• auto_increment: 16,790,881

DataCite queue:

• total count: 13361640
• size: 696MB
• auto_increment: 16,790,876

SearchIndexer queue:

• total count: 14804178
• size: 778MB
• auto_increment: 20,008,998

RefIdentifier table:

• total count:
• size: 4.12GB
• auto_increment: 49,875,699

Queue stats before:

ezid@uc3-ezidui-prd01:05:08:11:~/ezid$ python manage.py diag-queue-stats
{
  "download": {},
  "binder": {
    "F": 6,
    "O": 4015090,
    "S": 7993776,
    "U": 669913
  },
  "datacite": {
    "F": 1565,
    "O": 5367787,
    "S": 7992232,
    "U": 28
  },
  "crossref": {
    "F": 3878,
    "I": 13330253,
    "O": 16969,
    "U": 28,
    "W": 99
  },
  "searchindexer": {
    "F": 54,
    "O": 5466911,
    "S": 9337175
  }
}

Dump files:

ezid@uc3-ezidui-prd01:05:17:53:~/tmp/ezid_sql_dump_files$ ls -l
total 3107532
-rw-r--r--. 1 ezid ezid 759329912 Oct 24 05:15 ezidapp_binderqueue_table_dump_20241024_051443.sql
-rw-r--r--. 1 ezid ezid 725560660 Oct 24 05:15 ezidapp_crossrefqueue_table_dump_20241024_051443.sql
-rw-r--r--. 1 ezid ezid 805112285 Oct 24 05:16 ezidapp_datacitequeue_table_dump_20241024_051443.sql
-rw-r--r--. 1 ezid ezid 892086020 Oct 24 05:16 ezidapp_searchindexerqueue_table_dump_20241024_051443.sql

Delete binder queue records:

• started: 5:18
• finished: 6:11

  mysql -h rds-uc3-ezid5-prd.cmcguhglinoa.us-west-2.rds.amazonaws.com -u ezidrw ezid -p < 723_delete_binder_queue.sql

Update queue status:

• started: 5:28
• finished: 6:04

  mysql -h rds-uc3-ezid5-prd.cmcguhglinoa.us-west-2.rds.amazonaws.com -u ezidrw ezid -p < 723_update_queue_status.sql

[jsjiang]

Queue stats after:

{
  "download": {},
  "binder": {},
  "datacite": {
    "F": 1565,
    "O": 13350075
  },
  "crossref": {
    "F": 3878,
    "I": 13320253,
    "O": 16903,
    "W": 99
  },
  "searchindexer": {
    "F": 54,
    "O": 14793602
  }
}

Binder queue table stats after batch delete:

• total count: 0
• size: 920MB (??)
• auto_increment: 15,686,114

Binder queue table stats after running the TRUNCATE table ezidapp_binderqueue; command:

• total count: 0
• size: 16KB
• auto_increment: 1

Note: It was probably better to use "TRUNCATE table" instead of "delete from table" initially. Delete took about 50 minutes while truncate only took a few seconds. Also truncate released disk space immediately.

[jsjiang]

Lessons learned:

1. "TRUNCATE table" is more efficient than "DELETE from table" in our use case since we do not need the roll back feature it provides.
2. Stop services on the EZID instance using the sudo cdlsysctl stop service command might have triggered restarting the services by the demon agent. Check with Ashley the relationships among the Nagios settings, the deployment configuration and the cdlsysctl command.

[jsjiang]

Questions:

• how to handle older error entries?

[jsjiang]

Deployed proc-cleanup-async-queues_v2.py on ezid-prd on Oct 30 with release v3.2.27