Big ISO media file upload to a catalog issue

[delgado2]

Hi guys,

I'm experiencing an issue when I try to upload a huge ISO media file to a catalog, due to the fact the whole operation is quite extensive in time so I reach some sort of time limit somewhere and I try to figure out which one exactly. All settings defined in vCloud Director Administration/General/Timeouts look good, e.g. big numbers enough, allowing for a transfer or a session not то be interrupted if less than 480 minutes for example.

The problem occurs at the end of the 2nd stage transfer (the import step), once the file is getting moved from /opt/vmware/vcloud-director/data/transfer to the actual location on the NFS storage I use.

That last part of the transfer (the "importing step") seems to take more than 60 minutes of time and for me looks like the reason why it doesn't complete successfully. The exact time passed as per the logs is  3,798,255 ms, which means about 63 minutes or just over 60, so the operation fails. Just trying to understand where's that 60 minutes (or other threshold) defined and how I can lift it up a bit.

The exact error message is:

Session has been opened for too long: storage-fabric-activity-pool-1353. Opened since: 3/23/20 3:09 AM

vcloud-container-debug.log.9:2020-03-23 04:12:52,432 | WARN     | storage-fabric-activity-pool-1353 | Conversation                   | Session has been opened for too long: storage-fabric-activity-pool-1353. Opened since: 3/23/20 3:09 AM. [Conversation: 4fb93070-c551-4782-a56d-5bdb25ac6a17, transaction fcec9d60-4029-4fb8-ae41-36b5b8880138, transactionDepth: 1] | requestId=eea900e4-2f7b-444c-9621-bc646909b85e,request=POST https://xxx.somecloud.com/api/catalog/02ef3f7d-21b6-4b3d-8dea-070be42c02ba/action/upload,requestTime... 29.0 vcd=112e34af-125e-4a5e-9b10-4ed45ae72455,task=b92d8d4f-a321-4e12-9889-cb046e2e354e activity=(com.vmware.vcloud.backendbase.management.system.TaskActivity,urn:uuid:b92d8d4f-a321-4e12-9889-cb046e2e354e) activity=(com.vmware.ssdc.backend.services.impl.CreateMediaActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243) activity=(com.vmware.vcloud.fabric.storage.media.impl.CreateFromImportActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243)

vcloud-container-debug.log.9:2020-03-23 04:12:52,486 | DEBUG    | storage-fabric-activity-pool-1353 | CreateFromImportActivity       | [Activity Execution] Partial failure during Activity execution - Handle: urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243, Current Phase: CreateFromImportActivity$CopyPhase | requestId=eea900e4-2f7b-444c-9621-bc646909b85e,request=POST https://xxx.somecloud.com/api/catalog/02ef3f7d-21b6-4b3d-8dea-070be42c02ba/action/upload,requestTime... 29.0 vcd=112e34af-125e-4a5e-9b10-4ed45ae72455,task=b92d8d4f-a321-4e12-9889-cb046e2e354e activity=(com.vmware.vcloud.backendbase.management.system.TaskActivity,urn:uuid:b92d8d4f-a321-4e12-9889-cb046e2e354e) activity=(com.vmware.ssdc.backend.services.impl.CreateMediaActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243) activity=(com.vmware.vcloud.fabric.storage.media.impl.CreateFromImportActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243)

vcloud-container-debug.log.9:2020-03-23 04:12:52,503 | DEBUG    | storage-fabric-activity-pool-1353 | CreateFromImportActivity       | [Activity Execution] Finished - Handle: urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243, Current Phase: CreateFromImportActivity$CopyPhase | requestId=eea900e4-2f7b-444c-9621-bc646909b85e,request=POST https://xxx.somecloud.com/api/catalog/02ef3f7d-21b6-4b3d-8dea-070be42c02ba/action/upload,requestTime... 29.0 vcd=112e34af-125e-4a5e-9b10-4ed45ae72455,task=b92d8d4f-a321-4e12-9889-cb046e2e354e activity=(com.vmware.vcloud.backendbase.management.system.TaskActivity,urn:uuid:b92d8d4f-a321-4e12-9889-cb046e2e354e) activity=(com.vmware.ssdc.backend.services.impl.CreateMediaActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243) activity=(com.vmware.vcloud.fabric.storage.media.impl.CreateFromImportActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243)

vcloud-container-debug.log.9:2020-03-23 04:12:52,503 | DEBUG    | storage-fabric-activity-pool-1353 | CreateFromImportActivity       | [Activity Execution] Phase CopyPhase completed in 3,798,255 ms. - Handle: urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243, Current Phase: CreateFromImportActivity$CopyPhase | requestId=eea900e4-2f7b-444c-9621-bc646909b85e,request=POST https://xxx.somecloud.com/api/catalog/02ef3f7d-21b6-4b3d-8dea-070be42c02ba/action/upload,requestTime... 29.0 vcd=112e34af-125e-4a5e-9b10-4ed45ae72455,task=b92d8d4f-a321-4e12-9889-cb046e2e354e activity=(com.vmware.vcloud.backendbase.management.system.TaskActivity,urn:uuid:b92d8d4f-a321-4e12-9889-cb046e2e354e) activity=(com.vmware.ssdc.backend.services.impl.CreateMediaActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243) activity=(com.vmware.vcloud.fabric.storage.media.impl.CreateFromImportActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243)

vcloud-container-debug.log.9:2020-03-23 04:12:52,503 | DEBUG    | storage-fabric-activity-pool-1353 | CreateFromImportActivity       | [Activity Execution] Activity completed in 3,798,255 ms. - Handle: urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243, Current Phase: CreateFromImportActivity$CopyPhase | requestId=eea900e4-2f7b-444c-9621-bc646909b85e,request=POST https://xxx.somecloud.com/api/catalog/02ef3f7d-21b6-4b3d-8dea-070be42c02ba/action/upload,requestTime... 29.0 vcd=112e34af-125e-4a5e-9b10-4ed45ae72455,task=b92d8d4f-a321-4e12-9889-cb046e2e354e activity=(com.vmware.vcloud.backendbase.management.system.TaskActivity,urn:uuid:b92d8d4f-a321-4e12-9889-cb046e2e354e) activity=(com.vmware.ssdc.backend.services.impl.CreateMediaActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243) activity=(com.vmware.vcloud.fabric.storage.media.impl.CreateFromImportActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243)

vcloud-container-info.log:2020-03-23 04:12:52,432 | WARN     | storage-fabric-activity-pool-1353 | Conversation                   | Session has been opened for too long: storage-fabric-activity-pool-1353. Opened since: 3/23/20 3:09 AM. [Conversation: 4fb93070-c551-4782-a56d-5bdb25ac6a17, transaction fcec9d60-4029-4fb8-ae41-36b5b8880138, transactionDepth: 1] | requestId=eea900e4-2f7b-444c-9621-bc646909b85e,request=POST https://xxx.somecloud.com/api/catalog/02ef3f7d-21b6-4b3d-8dea-070be42c02ba/action/upload,requestTime... 29.0 vcd=112e34af-125e-4a5e-9b10-4ed45ae72455,task=b92d8d4f-a321-4e12-9889-cb046e2e354e activity=(com.vmware.vcloud.backendbase.management.system.TaskActivity,urn:uuid:b92d8d4f-a321-4e12-9889-cb046e2e354e) activity=(com.vmware.ssdc.backend.services.impl.CreateMediaActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243) activity=(com.vmware.vcloud.fabric.storage.media.impl.CreateFromImportActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243)

vcloud-container-info.log:2020-03-23 04:12:52,408 | ERROR    | storage-fabric-activity-pool-1355 | FutureUtil                     | Future /vcd01/media/1992ea7e-8949-46d4-b67d-da866dd13d28/cb937566-3564-419e-8c4f-2cdb1ca9943f/media-37441614-ac3f-4e88-8ee3-d57ba6d170e7.iso failed | requestId=eea900e4-2f7b-444c-9621-bc646909b85e,request=POST https://xxx.somecloud.com/api/catalog/02ef3f7d-21b6-4b3d-8dea-070be42c02ba/action/upload,requestTime... 29.0 vcd=112e34af-125e-4a5e-9b10-4ed45ae72455,task=b92d8d4f-a321-4e12-9889-cb046e2e354e activity=(com.vmware.vcloud.backendbase.management.system.TaskActivity,urn:uuid:b92d8d4f-a321-4e12-9889-cb046e2e354e) activity=(com.vmware.ssdc.backend.services.impl.CreateMediaActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243) activity=(com.vmware.vcloud.fabric.storage.media.impl.CreateFromImportActivity,urn:uuid 2efd67b4-bcee-45dd-b9b0-6924faca9243) activity=(com.vmware.vcloud.fabric.storage.copy.impl.UploadDatastoreFilesActivity,urn:uuid:4fc243d5-6ef8-4266-957b-63c32b7e44dd)

vcloud-container-info.log:2020-03-23 04:12:52,432 | WARN     | storage-fabric-activity-pool-1353 | Conversation                   | Session has been opened for too long: storage-fabric-activity-pool-1353. Opened since: 3/23/20 3:09 AM. [Conversation: 4fb93070-c551-4782-a56d-5bdb25ac6a17, transaction fcec9d60-4029-4fb8-ae41-36b5b8880138, transactionDepth: 1] | requestId=eea900e4-2f7b-444c-9621-bc646909b85e,request=POST https://xxx.somecloud.com/api/catalog/02ef3f7d-21b6-4b3d-8dea-070be42c02ba/action/upload,requestTime... 29.0 vcd=112e34af-125e-4a5e-9b10-4ed45ae72455,task=b92d8d4f-a321-4e12-9889-cb046e2e354e activity=(com.vmware.vcloud.backendbase.management.system.TaskActivity,urn:uuid:b92d8d4f-a321-4e12-9889-cb046e2e354e) activity=(com.vmware.ssdc.backend.services.impl.CreateMediaActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243) activity=(com.vmware.vcloud.fabric.storage.media.impl.CreateFromImportActivity,urn:uuid:2efd67b4-bcee-45dd-b9b0-6924faca9243)

Cheers!

[jnivoit]

Sounds like a bug to me, it usually means we're holding a DB transaction open while processing bytes (which we should not be doing), and then run into the DB transaction timeout.