Problem updating from 5.12.4 to 5.12.7. Stuck at [MIGRATION] #5244

AlexSanchezN · 2023-12-16T12:47:09Z

Description

I'm trying to update from 5.12.4. I've tried with 5.12.6 and 5.12.7 versions but the errors below appear during migration.
Tried to go to 5.12.4 again, but it did not work either. So I'm stuck without the platform :-(
Maybe it will solve itself by waiting if the migration is very long, but as the redis errors appear I've labeled this as a bug. Admins feel free to change it.
At the moment It is trying to upgrade to 5.12.7 since 12/16/2023 12:40
It has been trying to upgrade to 5.12.6 from 12/15/2023 21:30 to 12/16/2023 12:30 repeating the error message about every 30 seconds.

{"category":"APP","level":"info","message":"[MIGRATION] Saving current configuration, 1701354091187-file_mappings.js","timestamp":"2023-12-16T12:21:40.808Z","version":"5.12.7"} {"category":"APP","level":"info","message":"[MIGRATION] Starting 1701354091161-files-registration.js","timestamp":"2023-12-16T12:21:40.808Z","version":"5.12.7"} {"category":"APP","level":"warn","locks":["{locks}:platform_init_lock"],"message":"[REDIS] Extending resources for long processing task","stack":"Error: \n at lockResource (/opt/opencti/build/src/database/redis.ts:318:28)\n at initialization_default (/opt/opencti/build/src/initialization.js:359:18)\n at platformStart (/opt/opencti/build/src/boot.js:231:11)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)","timestamp":"2023-12-16T12:22:29.381Z","version":"5.12.7"} {"category":"APP","level":"warn","locks":["{locks}:platform_init_lock"],"message":"[REDIS] Extending resources for long processing task","stack":"Error: \n at lockResource (/opt/opencti/build/src/database/redis.ts:318:28)\n at initialization_default (/opt/opencti/build/src/initialization.js:359:18)\n at platformStart (/opt/opencti/build/src/boot.js:231:11)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)","timestamp":"2023-12-16T12:23:18.780Z","version":"5.12.7"} {"category":"APP","level":"warn","locks":["{locks}:platform_init_lock"],"message":"[REDIS] Extending resources for long processing task","stack":"Error: \n at lockResource (/opt/opencti/build/src/database/redis.ts:318:28)\n at initialization_default (/opt/opencti/build/src/initialization.js:359:18)\n at platformStart (/opt/opencti/build/src/boot.js:231:11)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)","timestamp":"2023-12-16T12:24:08.178Z","version":"5.12.7"} {"category":"APP","level":"warn","locks":["{locks}:platform_init_lock"],"message":"[REDIS] Extending resources for long processing task","stack":"Error: \n at lockResource (/opt/opencti/build/src/database/redis.ts:318:28)\n at initialization_default (/opt/opencti/build/src/initialization.js:359:18)\n at platformStart (/opt/opencti/build/src/boot.js:231:11)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)","timestamp":"2023-12-16T12:24:57.576Z","version":"5.12.7"} {"category":"APP","level":"warn","locks":["{locks}:platform_init_lock"],"message":"[REDIS] Extending resources for long processing task","stack":"Error: \n at lockResource (/opt/opencti/build/src/database/redis.ts:318:28)\n at initialization_default (/opt/opencti/build/src/initialization.js:359:18)\n at platformStart (/opt/opencti/build/src/boot.js:231:11)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)","timestamp":"2023-12-16T12:25:46.976Z","version":"5.12.7"} {"category":"APP","level":"warn","locks":["{locks}:platform_init_lock"],"message":"[REDIS] Extending resources for long processing task","stack":"Error: \n at lockResource (/opt/opencti/build/src/database/redis.ts:318:28)\n at initialization_default (/opt/opencti/build/src/initialization.js:359:18)\n at platformStart (/opt/opencti/build/src/boot.js:231:11)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)","timestamp":"2023-12-16T12:26:36.375Z","version":"5.12.7"} {"category":"APP","level":"warn","locks":["{locks}:platform_init_lock"],"message":"[REDIS] Extending resources for long processing task","stack":"Error: \n at lockResource (/opt/opencti/build/src/database/redis.ts:318:28)\n at initialization_default (/opt/opencti/build/src/initialization.js:359:18)\n at platformStart (/opt/opencti/build/src/boot.js:231:11)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)","timestamp":"2023-12-16T12:27:25.774Z","version":"5.12.7"}

Environment

Ubuntu 22.04 baremetal with healthy Redis

CPU Use: (The drop shows when we stopped the platform to upgrade)

Memory Use:

Redis instantaneous bytes/second:

Redis instantaneous operations/second:

The text was updated successfully, but these errors were encountered:

AlexSanchezN · 2023-12-16T13:46:33Z

More information from the process we left working at night, upgrade to 5.12.6 from 12/15/2023 21:30 to 12/16/2023 12:30, In the error log, there are the 2 lines shown below.
The second line is 502MB long, looks like a bulk operation on all the files in the platform.
I've splited it for readability

ABOUT 502MB of text

Tribe_ Evolution analysis, part 2 _ Securelist.pdf\",\"standard_id\":\"50788d8e-69df-5bf1-9aed-3e5074f2a9c9\",\"entity_type\":\"InternalFile\"}\n","headers":{"accept":"application/vnd.elasticsearch+json; compatible-with=8","content-length":"484894437","content-type":"application/vnd.elasticsearch+x-ndjson; compatible-with=8","user-agent":"elasticsearch-js/8.11.0 (linux 5.15.0-91-generic-x64; Node.js 18.17.1; Transport 8.4.0)","x-elastic-client-meta":"es=8.11.0,js=18.17.1,t=8.4.0,hc=18.17.1"},"method":"POST","path":"/_bulk","querystring":"refresh=true&timeout=5m"}}},"statusCode":413,"warnings":null},"name":"ResponseError","options":{"redaction":{"additionalKeys":[],"type":"replace"}}},"http_status":500,"reason":"[OPENCTI] Platform initialization fail"},"message":"An unknown error has occurred","name":"UnknownError","stack":"UnknownError: An unknown error has occurred\n at error (/opt/opencti/build/src/config/errors.js:8:10)\n at UnknownError (/opt/opencti/build/src/config/errors.js:72:47)\n at platformInit (/opt/opencti/build/src/initialization.js:386:13)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)\n at platformStart (/opt/opencti/build/src/boot.js:231:5)"},"level":"error","message":"[OPENCTI] Platform start fail","timestamp":"2023-12-16T02:09:28.427Z","version":"5.12.6"}

…tion (#5244)

richard-julien · 2023-12-16T17:05:34Z

Seems related to lot of files in your s3. PR open to prevent too many operations done at the same time

…tion (#5244)

SamuelHassine · 2023-12-17T08:56:20Z

Hello @AlexSanchezN,

Thanks for reporting this. Release 5.12.8 should solve your problem.

Kind regards,
Samuel

AlexSanchezN · 2023-12-17T11:36:54Z

Updating right now.
Will let you know.

Thanks for your effort. Very much appreciated

AlexSanchezN · 2023-12-17T11:51:20Z

It has been upgrading for 10 minutes now.
The errors below appear in opencti.log.2023-12-17
But no errors in error.log.2023-12-17 at the moment

{"category":"APP","level":"warn","locks":["{locks}:platform_init_lock"],"message":"[REDIS] Extending resources for long processing task","stack":"Error: \n at lockResource (/opt/opencti/build/src/database/redis.ts:318:28)\n at initialization_default (/opt/opencti/build/src/initialization.js:359:18)\n at platformStart (/opt/opencti/build/src/boot.js:231:11)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)","timestamp":"2023-12-17T11:41:36.676Z","version":"5.12.8"} {"category":"APP","level":"warn","locks":["{locks}:platform_init_lock"],"message":"[REDIS] Extending resources for long processing task","stack":"Error: \n at lockResource (/opt/opencti/build/src/database/redis.ts:318:28)\n at initialization_default (/opt/opencti/build/src/initialization.js:359:18)\n at platformStart (/opt/opencti/build/src/boot.js:231:11)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)","timestamp":"2023-12-17T11:42:26.118Z","version":"5.12.8"} {"category":"APP","level":"warn","locks":["{locks}:platform_init_lock"],"message":"[REDIS] Extending resources for long processing task","stack":"Error: \n at lockResource (/opt/opencti/build/src/database/redis.ts:318:28)\n at initialization_default (/opt/opencti/build/src/initialization.js:359:18)\n at platformStart (/opt/opencti/build/src/boot.js:231:11)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)","timestamp":"2023-12-17T11:43:15.535Z","version":"5.12.8"} {"category":"APP","level":"warn","locks":["{locks}:platform_init_lock"],"message":"[REDIS] Extending resources for long processing task","stack":"Error: \n at lockResource (/opt/opencti/build/src/database/redis.ts:318:28)\n at initialization_default (/opt/opencti/build/src/initialization.js:359:18)\n at platformStart (/opt/opencti/build/src/boot.js:231:11)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)","timestamp":"2023-12-17T11:44:04.982Z","version":"5.12.8"} {"category":"APP","level":"warn","locks":["{locks}:platform_init_lock"],"message":"[REDIS] Extending resources for long processing task","stack":"Error: \n at lockResource (/opt/opencti/build/src/database/redis.ts:318:28)\n at initialization_default (/opt/opencti/build/src/initialization.js:359:18)\n at platformStart (/opt/opencti/build/src/boot.js:231:11)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)","timestamp":"2023-12-17T11:44:54.403Z","version":"5.12.8"} {"category":"APP","level":"warn","locks":["{locks}:platform_init_lock"],"message":"[REDIS] Extending resources for long processing task","stack":"Error: \n at lockResource (/opt/opencti/build/src/database/redis.ts:318:28)\n at initialization_default (/opt/opencti/build/src/initialization.js:359:18)\n at platformStart (/opt/opencti/build/src/boot.js:231:11)\n at processTicksAndRejections (node:internal/process/task_queues:95:5)","timestamp":"2023-12-17T11:45:43.807Z","version":"5.12.8"}

There are over 530.000 objects in the Minio bucket, so I suppose we have to wait

richard-julien · 2023-12-17T12:49:09Z

500K files .. thats a lot :)
There is a progression log but in INFO level :(
Yes please wait for the end. If you kill and restart in INFO level it will restart the index from the beginning.

AlexSanchezN · 2023-12-17T15:28:45Z

The process finished correctly in 5.12.8.
Platform is up and running well.

Thanks again for your work, especially as it has been over the weekend

richard-julien · 2023-12-17T18:54:01Z

Cool news. Thanks for sharing. Any idea of the time it required to migrate the 500K files?

AlexSanchezN · 2023-12-19T19:59:05Z

Sorry for the late answer.
Find attached the complete log of the migration.
It looks like counting files took forever, after that the process was fast enough

Migration.txt

richard-julien · 2023-12-19T23:58:41Z

4 hours to get the list from S3/Minio and then 1 minute to index everything in elastic.
Thats the main reason we decide to mirror the list of files in elastic to be able to do quick operations instead of using the S3 Api.
Thanks for these metrics.

AlexSanchezN added bug use for describing something not working as expected needs triage use to identify issue needing triage from Filigran Product team labels Dec 16, 2023

richard-julien added a commit that referenced this issue Dec 16, 2023

[backend] Too many files in minio can prevent correct migration execu…

676e879

…tion (#5244)

richard-julien added a commit that referenced this issue Dec 16, 2023

[backend] Too many files in minio can prevent correct migration execu…

c1d5021

…tion (#5244)

richard-julien mentioned this issue Dec 16, 2023

[backend] Too many files in minio can prevent correct migration execution (#5244) #5245

Merged

richard-julien removed the needs triage use to identify issue needing triage from Filigran Product team label Dec 16, 2023

SamuelHassine pushed a commit that referenced this issue Dec 17, 2023

[backend] Too many files in minio can prevent correct migration execu…

b0e5b0e

…tion (#5244)

SamuelHassine added the solved use to identify issue that has been solved (must be linked to the solving PR) label Dec 17, 2023

SamuelHassine closed this as completed Dec 17, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Problem updating from 5.12.4 to 5.12.7. Stuck at [MIGRATION] #5244

Problem updating from 5.12.4 to 5.12.7. Stuck at [MIGRATION] #5244

AlexSanchezN commented Dec 16, 2023

AlexSanchezN commented Dec 16, 2023

richard-julien commented Dec 16, 2023

SamuelHassine commented Dec 17, 2023

AlexSanchezN commented Dec 17, 2023

AlexSanchezN commented Dec 17, 2023

richard-julien commented Dec 17, 2023

AlexSanchezN commented Dec 17, 2023

richard-julien commented Dec 17, 2023

AlexSanchezN commented Dec 19, 2023

richard-julien commented Dec 19, 2023

Problem updating from 5.12.4 to 5.12.7. Stuck at [MIGRATION] #5244

Problem updating from 5.12.4 to 5.12.7. Stuck at [MIGRATION] #5244

Comments

AlexSanchezN commented Dec 16, 2023

Description

Environment

AlexSanchezN commented Dec 16, 2023

richard-julien commented Dec 16, 2023

SamuelHassine commented Dec 17, 2023

AlexSanchezN commented Dec 17, 2023

AlexSanchezN commented Dec 17, 2023

richard-julien commented Dec 17, 2023

AlexSanchezN commented Dec 17, 2023

richard-julien commented Dec 17, 2023

AlexSanchezN commented Dec 19, 2023

richard-julien commented Dec 19, 2023