Undo function not triggered when upload to S3 fails

Question

Undo function not triggered when upload to S3 fails

Opened this issue 6 years ago · 0 comments

During the testing of the SRS_STS pipeline, it appeared that there are some cases not covered by the undo functionality allowing a harvester to list files that are not available in S3.
SRS_SST files need to be harvested by both the generic_timestep harvester and the SRS_SST harvester. In my test, the SRS_SST file was successfully harvested by the generic_timestep harvester, but the next action which is the upload to S3 failed. No action was triggered to unharvest the file from the generic_timestep harvester.
See the logs below for the full details:

2018-03-29 12:52:54,194 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] IncomingFileStateManager initialised in state: FILE_IN_INCOMING
2018-03-29 12:52:54,529 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] IncomingFileStateManager transitioned to state: FILE_IN_PROCESSING
2018-03-29 12:52:54,576 INFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] running handler -> 'SrsGhrsstHandler({'collection_dir': '/tmp/SrsGhrsstHandlerEq2urW/collection', 'dest_path_function': None, 'file_type': <FileType.NETCDF: ('.nc', 'application/octet-stream')>, 'should_notify': None, 'resolve_params': None, 'file_checksum': None, 'instance_working_directory': '/tmp/SrsGhrsstHandlerEq2urW', 'celery_task_id': '7b89409d-35fe-45ca-823b-a688c0c4477b', 'result': <HandlerResult.UNKNOWN: 0>, 'exclude_regexes': None, 'include_regexes': None, 'cc_versions': None, 'products_dir': '/tmp/SrsGhrsstHandlerEq2urW/products', 'check_params': None, 'notification_results': None, 'error_details': None, 'temp_dir': '/tmp/SrsGhrsstHandlerEq2urW/temp', 'file_extension': u'.nc', 'archive_path_function': None, 'archive_input_file': False, 'input_file': u'/vagrant/src/processing/SRS_GHRSST/7b89409d-35fe-45ca-823b-a688c0c4477b/20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc', 'start_time': datetime.datetime(2018, 3, 29, 12, 52, 54, 529320), 'harvest_params': None, 'upload_path': u'SRS/SST/20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc', 'harvest_type': 'talend', 'celery_task_name': 'tasks.SRS_GHRSST', 'notify_params': None, 'file_collection': PipelineFileCollection([]), 'allowed_extensions': ['.nc'], 'is_archived': False, 'error': None})'
2018-03-29 12:52:54,848 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] get_file_checksum -> '1dc069decc000441c818cf7eef10b5b5fca1ddb2d397fad9e3832d500d512169'
2018-03-29 12:52:54,848 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] get_cc_module_versions -> {'core': '3.1.1', 'plugin': '1.2.0'}
2018-03-29 12:52:54,848 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] get_path_function -> 'SrsGhrsstHandler.dest_path'
2018-03-29 12:52:54,848 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] get_path_function (archive) -> 'SrsGhrsstHandler.dest_path'
2018-03-29 12:52:54,848 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] SrsGhrsstHandler transitioned to state: HANDLER_INITIALISED
2018-03-29 12:52:54,848 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] get_resolve_runner -> 'SingleFileResolveRunner'
2018-03-29 12:52:55,056 INFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] file: '20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc' updated: {'publish_type': 'HARVEST_UPLOAD'}
2018-03-29 12:52:55,056 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] SrsGhrsstHandler transitioned to state: HANDLER_RESOLVED
2018-03-29 12:52:55,056 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] `preprocess` not overridden by child class, skipping step
2018-03-29 12:52:55,056 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] SrsGhrsstHandler transitioned to state: HANDLER_PREPROCESSED
2018-03-29 12:52:55,056 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] get_check_runner -> 'CheckRunnerAdapter'
2018-03-29 12:52:55,056 INFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] file: '20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc' updated: {'check_type': 'FORMAT_CHECK'}
2018-03-29 12:52:55,057 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] get_child_check_runner -> 'FormatCheckRunner'
2018-03-29 12:52:55,057 INFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] checking that '/tmp/SrsGhrsstHandlerEq2urW/collection/20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc' is a valid NetCDF file
2018-03-29 12:52:55,063 INFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] file: '20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc' updated: {'is_checked': True}
2018-03-29 12:52:55,063 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] SrsGhrsstHandler transitioned to state: HANDLER_CHECKED
2018-03-29 12:52:55,064 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] `process` not overridden by child class, skipping step
2018-03-29 12:52:55,064 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] SrsGhrsstHandler transitioned to state: HANDLER_PROCESSED
2018-03-29 12:52:55,064 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] get_upload_runner (archive) -> 'FileUploadRunner'
2018-03-29 12:52:55,064 SYSINFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] get_upload_runner -> 'FileUploadRunner'
2018-03-29 12:52:55,064 INFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] file: '20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc' updated: {'dest_path': u'IMOS/SRS/SST/ghrsst/L3C-1d/day/n19/2018/20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc'}
2018-03-29 12:52:55,065 INFO tasks.SRS_GHRSST[7b89409d-35fe-45ca-823b-a688c0c4477b] file: '20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc' updated: {'is_overwrite': False}
2018-03-29 11:17:43,690 INFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] checking that '/tmp/SrsGhrsstHandler1auFhJ/collection/20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc' is a
valid NetCDF file
2018-03-29 11:17:43,698 INFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] file: '20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc' updated: {'is_checked': True}
2018-03-29 11:17:43,698 SYSINFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] SrsGhrsstHandler transitioned to state: HANDLER_CHECKED
2018-03-29 11:17:43,699 SYSINFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] `process` not overridden by child class, skipping step
2018-03-29 11:17:43,699 SYSINFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] SrsGhrsstHandler transitioned to state: HANDLER_PROCESSED
2018-03-29 11:17:43,699 SYSINFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] get_upload_runner (archive) -> 'FileUploadRunner'
2018-03-29 11:17:43,699 SYSINFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] get_upload_runner -> 'FileUploadRunner'
2018-03-29 11:17:43,704 INFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] file: '20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc' updated: {'dest_path': u'IMOS/SRS/SST/ghrsst/L3C-1d/
day/n19/2018/20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc'}
2018-03-29 11:17:43,704 INFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] file: '20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc' updated: {'is_overwrite': False}
2018-03-29 11:17:43,705 SYSINFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] get_harvester_runner -> 'TalendHarvesterRunner'
2018-03-29 11:17:43,705 SYSINFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] harvesting slice size: 2048
2018-03-29 11:17:43,729 SYSINFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] harvester 'srs_ghrsst_gridded-srs_ghrsst_gridded' matched file: /tmp/SrsGhrsstHandler1auFhJ/collection/2018032603200
0-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc
2018-03-29 11:17:43,732 SYSINFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] harvester 'srs_sst-srs_sst' matched file: /tmp/SrsGhrsstHandler1auFhJ/collection/20180326032000-ABOM-L3C_GHRSST-SSTs
kin-AVHRR19_D-1d_day.nc
2018-03-29 11:17:43,734 INFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] running additions for harvester 'srs_ghrsst_gridded-srs_ghrsst_gridded'
2018-03-29 11:17:43,734 SYSINFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] executing /usr/local/talend/jobs/srs_ghrsst_gridded-srs_ghrsst_gridded/java/GENERIC_TIMESTEP_harvester/GENERIC_TIMES
TEP_harvester_run.sh --context_param paramFile="/usr/local/talend/jobs/srs_ghrsst_gridded-srs_ghrsst_gridded/etc/srs_ghrsst_gridded-srs_ghrsst_gridded.conf" --context_param base=/tmp/SrsGhrsstHandler1auF
hJ/temp/talend_basemLibiJ --context_param fileList=/tmp/SrsGhrsstHandler1auFhJ/temp/talend_basemLibiJ/file_listNtp50A.txt --context_param logDir=/mnt/ebs/log/pipeline/process --context_param collection=s
rs_ghrsst_l3c_1d_day_n19
2018-03-29 11:17:43,735 INFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] --- START TALEND OUTPUT ---
file: '20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc' updated: {'is_harvested': True}
INFO 3/29/18 11:17 AM:liquibase: Successfully acquired change log lock
INFO 3/29/18 11:17 AM:liquibase: Reading from generic_timestep.databasechangelog
INFO 3/29/18 11:17 AM:liquibase: Reading from generic_timestep.databasechangelog
INFO 3/29/18 11:17 AM:liquibase: Successfully released change log lock
Start of try block
tempFile_cid /tmp/talend-temp-509538281113409734/changelog.xml
***********************
conn host:localhost, port:5432, schema:generic_timestep, name:harvest?loginTimeout=1000&ssl=true&sslfactory=org.postgresql.ssl.NonValidatingFactory, user:generic_timestep
url_cid:jdbc:postgresql://localhost:5432/harvest?loginTimeout=1000&ssl=true&sslfactory=org.postgresql.ssl.NonValidatingFactory
schema_cid:generic_timestep
userName_cid:generic_timestep
INFO 3/29/18 11:17 AM:liquibase: Successfully acquired change log lock
INFO 3/29/18 11:17 AM:liquibase: Reading from generic_timestep.databasechangelog
INFO 3/29/18 11:17 AM:liquibase: Reading from generic_timestep.databasechangelog
INFO 3/29/18 11:17 AM:liquibase: Successfully released change log lock
***** completed finally block ***********
In finally block
SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
* iNewOrModifiedFileList_1 modified/new resource file_id=6

--- END TALEND OUTPUT ---
2018-03-29 11:17:47,349 INFO tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] uploading '/tmp/SrsGhrsstHandler1auFhJ/collection/20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc' to 'file:///s3/imos-data/IMOS/SRS/SST/ghrsst/L3C-1d/day/n19/2018/20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc'
2018-03-29 11:17:47,349 ERROR tasks.SRS_GHRSST[7434c57b-3d40-4b02-8a1e-858c33c666cc] FileUploadFailedError: OSError: [Errno 13] Permission denied: '/s3/imos-data/IMOS/SRS/SST/ghrsst/L3C-1d/day/n19/2018/tmp2CJGR0': 'IMOS/SRS/SST/ghrsst/L3C-1d/day/n19/2018/20180326032000-ABOM-L3C_GHRSST-SSTskin-AVHRR19_D-1d_day.nc'