Lengthy and error-triggering post-upgrade operations

[talcher]

Hello the EJBCA team,

I followed the documentation for the upgrading of EJBCA: it is nicely written; thanks a lot!

My aim was to jump from version 6.15 to version 8.0 - running on a WildFly 26 server -, by clicking on "Start post-upgrade" on the "System Upgrade" page of the WebAdmin UI.
I have 4 questions:

• I have not been able to perform the full jump at once. I had to click twice on the "Start post-upgrade" button. The first time, it was to launch the process at the beginning. I ended up with this situation:
  
  So, I clicked again on the still present "Start post-upgrade" button, and it went smootlhy to this situation:
  
  => is this two-step process expected, or have I made a mistake?
• the first step was quite lengthy: it took 1h to update the 'crldata_idx3' index, despite a fairly light MySQL database: ~ 26MB.

2023-10-24 16:49:24,495 INFO [org.ejbca.core.ejb.upgrade.UpgradeSessionBean] (EJB default - 1) Successfully updated index 'crldata_idx3' for database table 'CRLData'. Completed in 3599944 ms.

=> is this behaviour expected, or have I made a mistake?

• at the end of the 1st step, a bunch of WARNINGS - 6 - and ERRORS - 7 - were logged. I can provide you with those logs, if you want.
  => is this behaviour expected, or have I made a mistake?
• finally, with the second screenshot, one could think that I am running v7.11.0 of EJBCA and not 8.0.
  => could you confirm that such a thought is a misinterpretation?

I hope I have made my points clear. Feel free to ask more insights if needed!

Thank you.

alcher

[primetomas]

Are you sure your database is only 26MB and not 260GB? The CRLData table may end up holding many records for sure, but for an index update to be so slow your database must really have very little RAM, slow disk, or something like that. It should be done in a few seconds. That is a database configuration issue though. You can see the SQL being executed in order to update the index and you can test that on your database to see why it is so slow.

[talcher]

Hello Tomas,

thank you for your answer.

As surprising as it may be, my database is fairly small: 26MB is the proper size, indeed.
I have double checked the resource consumption of my database server with the htop command, when I click on the "Start post-upgrade" button: the change was nearly invisible, and one quarter of the RAM is free. My hard disk is nearly empty, as well.
So, the first logs are OK:

Database content version: 6.10.1, current application version: 8.0 -> Starting post-upgrade.
Starting post upgrade to 7.2.0
Post upgrade to 7.2.0 complete.
Starting post upgrade to 7.4.0
Successfully normalized 369 rows in CRLData. Completed in 153 ms.

Then, nothing happens for one hour...

When you wrote "You can see the SQL being executed in order to update the index and you can test that on your database to see why it is so slow.", did you mean activating the bin logs?
I have never done so, but I can give it a try of course.

Have a nice week-end!

[talcher]

Hello Tomas,
I have set up the bin logs. Here are the results, in the order they appear in the logs:

1. The last "quick"/"normal" action

The first logs are:

#231107 10:49:04 server id 1 end_log_pos 1636933 CRC32 0xc4e870fd GTID 0-1-292 trans
/!100001 SET @@session.gtid_seq_no=292//!/;
START TRANSACTION
/!/;
# at 1636933
# at 1637072
#231107 10:49:03 server id 1 end_log_pos 1637072 CRC32 0x865f8a9f Annotate_rows:
#Q> UPDATE CRLData a SET a.crlPartitionIndex = -1 WHERE a.crlPartitionIndex IS NULL OR a.crlPartitionIndex=0 LIMIT 1000
#231107 10:49:03 server id 1 end_log_pos 1637142 CRC32 0x02e6c816 Table_map: acdiv.CRLData mapped to number 233
# at 1637142
# at 1644328
# at [...]

Many similar lines, and finally:

#231107 10:49:03 server id 1 end_log_pos 1644328 CRC32 0x890a7e63 Update_rows: table id 233
#231107 10:49:03 server id 1 end_log_pos [...]

Many similar lines, and finally:

#231107 10:49:03 server id 1 end_log_pos 2812682 CRC32 0x7a1b8dcd Update_rows: table id 233 flags: STMT_END_F

Then, the Base64 logs, and finally:

# Number of rows: 369
# at 2812682
#231107 10:49:04 server id 1 end_log_pos 2812713 CRC32 0x17e44772 Xid = 1407
COMMIT/!/;
# at 2812713

2. My being automatically logged out of the WebUI

It starts with that:

#231107 11:04:35 server id 1 end_log_pos 2812755 CRC32 0x3ad4af79 GTID 0-1-293 trans

But for the time, it is of no interest.

3. The index management

#231107 10:49:04 server id 1 end_log_pos 2814366 CRC32 0x1e3d045c GTID 0-1-294 ddl
/!100001 SET @@session.gtid_seq_no=294//!/;
# at 2814366
#231107 10:49:04 server id 1 end_log_pos 2814477 CRC32 0x8fd64d65 Query thread_id=37 exec_time=3600 error_code=0 xid=1413
SET TIMESTAMP=1699350544/!/;
DROP INDEX crldata_idx3 ON CRLData
/!/;
# at 2814477
#231107 11:49:04 server id 1 end_log_pos 2814519 CRC32 0x0abbcd0f GTID 0-1-295 ddl
/!100001 SET @@session.gtid_seq_no=295//!/;
# at 2814519
#231107 11:49:04 server id 1 end_log_pos 2814672 CRC32 0xe26566db Query thread_id=37 exec_time=0 error_code=0 xid=3795
SET TIMESTAMP=1699354144/!/;
CREATE INDEX crldata_idx5 ON CRLData(cRLNumber, issuerDN, crlPartitionIndex)
/!/;
# at 2814672
#231107 11:49:04 server id 1 end_log_pos 2814714 CRC32 0x2d1eb8c9 GTID 0-1-296 ddl
/!100001 SET @@session.gtid_seq_no=296//!/;
# at 2814714
#231107 11:49:04 server id 1 end_log_pos 2814825 CRC32 0xb16d75b4 Query thread_id=37 exec_time=0 error_code=0 xid=3799
SET TIMESTAMP=1699354144/!/;
DROP INDEX crldata_idx4 ON CRLData
/!/;
# at 2814825
#231107 11:49:04 server id 1 end_log_pos 2814867 CRC32 0xf95a8b2a GTID 0-1-297 ddl
/!100001 SET @@session.gtid_seq_no=297//!/;
# at 2814867
#231107 11:49:04 server id 1 end_log_pos 2815046 CRC32 0x5e9b802f Query thread_id=37 exec_time=0 error_code=0 xid=3800
SET TIMESTAMP=1699354144/!/;
CREATE UNIQUE INDEX crldata_idx6 ON CRLData(issuerDN, crlPartitionIndex, deltaCRLIndicator, cRLNumber)
/!/;
# at 2815046

I can confirm that, apart from my being automatically logged out of the WebUI, there is absolutely no action between the 1st and 3rd points above. The database server is totally idle.

After reading the code (2197-2250), I have tried modifying manually the database, with the database restored to the pre-upgrade situation. Here are the commands executed on the database directly, and their results:

MariaDB [ejbca]> DROP INDEX crldata_idx3 ON CRLData;
Query OK, 369 rows affected (0,084 sec)
Records: 369 Duplicates: 0 Warnings: 0

MariaDB [ejbca]> ALTER TABLE CRLData ADD crlPartitionIndex INT(11);
Query OK, 0 rows affected (0,081 sec)
Records: 0 Duplicates: 0 Warnings: 0

MariaDB [ejbca]> CREATE INDEX crldata_idx5 ON CRLData(cRLNumber, issuerDN, crlPartitionIndex);
Query OK, 0 rows affected (0,012 sec)
Records: 0 Duplicates: 0 Warnings: 0

As you can notice, the whole process took me fairly less than 1h.

Any suggestion on the topic would be greatly appreciated.
Thank you,

alcher

[primetomas]

After your manual update it the system works as expected?
I didn't see what database you use btw?
It seems like there is no database operation that takes long time.

[talcher]

Hello Tomas,

I use MariaDB 10.11.

I had to run, directly on the database, both commands DROP INDEX crldata_idx3 ON CRLData; and DROP INDEX crldata_idx4 ON CRLData;, for the post-upgrade operation to be carried out smoothly.
Of course, I had to create the proper indexes later on directly on the database.

If I did not drop both of the indexes myself - dropping only one or the other was not enough -, I always had to wait for one hour before those events to be logged on:

WARN [com.arjuna.ats.arjuna] (Transaction Reaper) ARJUNA012117: TransactionReaper::check processing TX 0:ffff0ae39289:825923f:65365f34:27b in state RUN

WARN [org.hibernate.resource.transaction.backend.jta.internal.synchronization.SynchronizationCallbackCoordinatorTrackingImpl] (Transaction Reaper Worker 0) HHH000451: Transaction afterCompletion called by a background thread; delaying afterCompletion processing until the original thread can handle it. [status=4]

It is as if the triggering of an action after a one-hour timeout woke up the whole process and made it move one step forward.
Does it ring a bell?

Cheers,

alcher

[primetomas]

Unfortunately it doesn't ring any bells at all. How many cores does the CPU you run on have?

[talcher]

It is a 2-core 2.60GHz x86_64 CPU.