Potential race condition in update_archival

[nuest]

In muncher, three containers are started for the respective brokerings. The brokerings normally complete fine, but sometimes there is an issue with updating the package slip file. In the following case, all brokerings complete as is visible in all brokering output files existing. But for zenodo_sandbox the update_archival returns an error:

muncher_1         | 2018-04-26T09:17:06.219Z muncher:compendium [KqPAH] Compendium is a candidate, need to make some checks.
muncher_1         | 2018-04-26T09:17:06.220Z muncher:compendium [KqPAH] Checking rights for user 0000-0001-6225-344X against level 500
muncher_1         | 2018-04-26T09:17:06.220Z muncher:compendium [KqPAH] User 0000-0001-6225-344X is owner!
muncher_1         | 2018-04-26T09:17:06.220Z muncher:compendium [KqPAH] User 0000-0001-6225-344X may see candidate metadata.
muncher_1         | 2018-04-26T09:17:06.246Z muncher REQUEST PUT /api/v1/compendium/KqPAH/metadata authenticated user: true | session: KEx684Az6lUPsmrAlOEOOJEiS4wTgaPC  | orcid: 0000-0001-6225-344X
muncher_1         | 2018-04-26T09:17:06.248Z muncher:compendium [KqPAH] Checking rights for user 0000-0001-6225-344X against level 500
muncher_1         | 2018-04-26T09:17:06.248Z muncher:compendium [KqPAH] User 0000-0001-6225-344X is owner!
muncher_1         | 2018-04-26T09:17:06.248Z muncher:bagit [KqPAH] Could not find bag detection file for compendium, NOT a bag: Error: ENOENT: no such file or directory, access '/tmp/o2r/compendium/KqPAH/bagit.txt'
muncher_1         | 2018-04-26T09:17:06.248Z muncher:compendium [KqPAH] Overwriting file /tmp/o2r/compendium/KqPAH/.erc/metadata_o2r_1.json
muncher_1         | 2018-04-26T09:17:06.250Z muncher:meta [KqPAH] Validating metadata file /tmp/o2r/compendium/KqPAH/.erc/metadata_o2r_1.json with schema schema/json/o2r-meta-schema.json
muncher_1         | 2018-04-26T09:17:06.250Z muncher:meta [KqPAH] volume is configured, overwriting binds configuration (was [ '/tmp/o2r/compendium/KqPAH/.erc/metadata_o2r_1.json:/tmp/o2r/compendium/KqPAH/.erc/metadata_o2r_1.json' ])
muncher_1         | 2018-04-26T09:17:06.251Z muncher:meta [KqPAH] Starting Docker container now with options and command:
muncher_1         |     create_options: {"CpuShares":128,"Env":["O2R_MUNCHER=true"],"Memory":1073741824,"MemorySwap":2147483648,"User":"root","name":"meta_validate_KqPAH_metadata_o2r_1.json","HostConfig":{"Binds":["o2rplatform_o2rstorage:/tmp/o2r/"],"AutoRemove":true}}
muncher_1         |     start_options: {}
muncher_1         |     cmd: -debug validate -s schema/json/o2r-meta-schema.json -c /tmp/o2r/compendium/KqPAH/.erc/metadata_o2r_1.json
muncher_1         | 2018-04-26T09:17:07.109Z muncher:meta [KqPAH] [validate container] [o2rmeta] 20180426.091707 received arguments: {'debug': True, 'tool': 'validate', 'schema': 'schema/json/o2r-meta-schema.json', 'candidate': '/tmp/o2r/compendium/KqPAH/.erc/metadata_o2r_1.json'}
muncher_1         | [o2rmeta] 20180426.091707 launching validator
muncher_1         | [o2rmeta] 20180426.091707 checking metadata_o2r_1.json against o2r-meta-schema.json
muncher_1         | 2018-04-26T09:17:07.115Z muncher:meta [KqPAH] [validate container] [o2rmeta] 20180426.091707 valid: /tmp/o2r/compendium/KqPAH/.erc/metadata_o2r_1.json
muncher_1         | 2018-04-26T09:17:07.587Z muncher:meta [KqPAH] container running: Container { modem: Modem { socketPath: '/var/run/docker.sock', host: undefined, port: undefined, version: undefined, key: undefined, cert: undefined, ca: undefined, timeout: undefined, checkServerIdentity: undefined, protocol: 'http', Promise: [Function: Promise] }, id: '083113d0f7b4c96fa0d9f5dfb8ae7b7de7002a098f72ff2f4a5c7bd3d6107373', defaultOptions: { top: {}, start: {}, commit: {}, stop: {}, pause: {}, unpause: {}, restart: {}, resize: {}, attach: {}, remove: {}, copy: {}, kill: {}, exec: {}, rename: {}, log: {}, stats: {}, getArchive: {}, infoArchive: {}, putArchive: {}, update: {} } }
muncher_1         | 2018-04-26T09:17:07.587Z muncher:meta [KqPAH] Completed metadata validation, container result: { Error: null, StatusCode: 0 }
muncher_1         | 2018-04-26T09:17:07.587Z muncher:meta [KqPAH] Metadata is VALID
muncher_1         | 2018-04-26T09:17:07.587Z muncher:meta [KqPAH] Brokering "zenodo" metadata (using input file /tmp/o2r/compendium/KqPAH/.erc/metadata_o2r_1.json) to directory /tmp/o2r/compendium/KqPAH/.erc
muncher_1         | 2018-04-26T09:17:07.587Z muncher:meta [KqPAH][zenodo] volume is configured, overwriting binds configuration (was [ '/tmp/o2r/compendium/KqPAH/.erc:/tmp/o2r/compendium/KqPAH/.erc' ])
muncher_1         | 2018-04-26T09:17:07.587Z muncher:meta [KqPAH][zenodo] Starting Docker container now with options and command:
muncher_1         |     create_options: {"CpuShares":128,"Env":["O2R_MUNCHER=true"],"Memory":1073741824,"MemorySwap":2147483648,"User":"root","name":"meta_broker_KqPAH_zenodo","HostConfig":{"Binds":["o2rplatform_o2rstorage:/tmp/o2r/"],"AutoRemove":true}}
muncher_1         |     start_options: {}
muncher_1         |     cmd: -debug broker --inputfile /tmp/o2r/compendium/KqPAH/.erc/metadata_o2r_1.json --map broker/mappings/zenodo-map.json --outputdir /tmp/o2r/compendium/KqPAH/.erc
muncher_1         | 2018-04-26T09:17:07.588Z muncher:meta [KqPAH] Brokering "zenodo_sandbox" metadata (using input file /tmp/o2r/compendium/KqPAH/.erc/metadata_o2r_1.json) to directory /tmp/o2r/compendium/KqPAH/.erc
muncher_1         | 2018-04-26T09:17:07.588Z muncher:meta [KqPAH][zenodo_sandbox] volume is configured, overwriting binds configuration (was [ '/tmp/o2r/compendium/KqPAH/.erc:/tmp/o2r/compendium/KqPAH/.erc' ])
muncher_1         | 2018-04-26T09:17:07.588Z muncher:meta [KqPAH][zenodo_sandbox] Starting Docker container now with options and command:
muncher_1         |     create_options: {"CpuShares":128,"Env":["O2R_MUNCHER=true"],"Memory":1073741824,"MemorySwap":2147483648,"User":"root","name":"meta_broker_KqPAH_zenodo_sandbox","HostConfig":{"Binds":["o2rplatform_o2rstorage:/tmp/o2r/"],"AutoRemove":true}}
muncher_1         |     start_options: {}
muncher_1         |     cmd: -debug broker --inputfile /tmp/o2r/compendium/KqPAH/.erc/metadata_o2r_1.json --map broker/mappings/zenodo_sandbox-map.json --outputdir /tmp/o2r/compendium/KqPAH/.erc
muncher_1         | 2018-04-26T09:17:08.751Z muncher:meta [KqPAH][zenodo] [broker container] [o2rmeta] 20180426.091708 received arguments: {'debug': True, 'tool': 'broker', 'check': None, 'map': 'broker/mappings/zenodo-map.json', 'inputfile': '/tmp/o2r/compendium/KqPAH/.erc/metadata_o2r_1.json', 'outputdir': '/tmp/o2r/compendium/KqPAH/.erc', 'outputtostdout': False}
muncher_1         | [o2rmeta] 20180426.091708 launching broker
muncher_1         | 2018-04-26T09:17:08.752Z muncher:meta [KqPAH][zenodo_sandbox] [broker container] [o2rmeta] 20180426.091708 received arguments: {'debug': True, 'tool': 'broker', 'check': None, 'map': 'broker/mappings/zenodo_sandbox-map.json', 'inputfile': '/tmp/o2r/compendium/KqPAH/.erc/metadata_o2r_1.json', 'outputdir': '/tmp/o2r/compendium/KqPAH/.erc', 'outputtostdout': False}
muncher_1         | [o2rmeta] 20180426.091708 launching broker
muncher_1         | 2018-04-26T09:17:08.753Z muncher:meta [KqPAH][zenodo] [broker container] [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <upload_type>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <title>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <publication_type>
muncher_1         | 2018-04-26T09:17:08.753Z muncher:meta [KqPAH][zenodo] [broker container] [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <publication_date>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <keywords>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <identifier>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <description>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <creators>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <communities>
muncher_1         | 2018-04-26T09:17:08.754Z muncher:meta [KqPAH][zenodo_sandbox] [broker container] [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <upload_type>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <title>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <publication_type>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <publication_date>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <keywords>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <identifier>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <description>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <creators>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <communities>
muncher_1         | [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <access_right>
muncher_1         | 2018-04-26T09:17:08.754Z muncher:meta [KqPAH][zenodo_sandbox] [broker container] [o2rmeta][debug: broker.metabroker @ do_outputs] 20180426.091708 1916 bytes written to /tmp/o2r/compendium/KqPAH/.erc/metadata_zenodo_sandbox_1.json
muncher_1         | 2018-04-26T09:17:08.754Z muncher:meta [KqPAH][zenodo] [broker container] [o2rmeta][debug: broker.metabroker @ map_json] 20180426.091708 processing element <access_right>
muncher_1         | 2018-04-26T09:17:08.754Z muncher:meta [KqPAH][zenodo_sandbox] [broker container] [o2rmeta][debug: broker.metabroker @ update_archival] 20180426.091708 Expecting value: line 1 column 1 (char 0)
muncher_1         | Traceback (most recent call last):
muncher_1         |   File "/o2r-meta/o2rmeta.py", line 81, in <module>
muncher_1         | 2018-04-26T09:17:08.755Z muncher:meta [KqPAH][zenodo_sandbox] [broker container] metabroker.start(dbg=argsd['debug'], c=argsd['check'], m=argsd['map'], i=argsd['inputfile'], o=argsd['outputdir'], s=argsd['outputtostdout'])
muncher_1         |   File "/o2r-meta/broker/metabroker.py", line 351, in start
muncher_1         | 2018-04-26T09:17:08.755Z muncher:meta [KqPAH][zenodo_sandbox] [broker container] do_outputs(json_output, output_mode, output_file_name)
muncher_1         |   File "/o2r-meta/broker/metabroker.py", line 76, in do_outputs
muncher_1         | 2018-04-26T09:17:08.755Z muncher:meta [KqPAH][zenodo_sandbox] [broker container] update_archival(out_mode)
muncher_1         |   File "/o2r-meta/broker/metabroker.py", line 89, in update_archival
muncher_1         | 2018-04-26T09:17:08.756Z muncher:meta [KqPAH][zenodo_sandbox] [broker container] data = json.load(data_file)
muncher_1         |   File "/usr/local/lib/python3.6/json/__init__.py", line 299, in load
muncher_1         | 2018-04-26T09:17:08.756Z muncher:meta [KqPAH][zenodo_sandbox] [broker container] parse_constant=parse_constant, object_pairs_hook=object_pairs_hook, **kw)
muncher_1         |   File "/usr/local/lib/python3.6/json/__init__.py", line 354, in loads
muncher_1         |     return _default_decoder.decode(s)
muncher_1         |   File "/usr/local/lib/python3.6/json/decoder.py", line 339, in decode
muncher_1         | 2018-04-26T09:17:08.756Z muncher:meta [KqPAH][zenodo] [broker container] [o2rmeta][debug: broker.metabroker @ do_outputs] 20180426.091708 1916 bytes written to /tmp/o2r/compendium/KqPAH/.erc/metadata_zenodo_1.json
muncher_1         | [o2rmeta][debug: broker.metabroker @ update_archival] 20180426.091708 0 bytes written to /tmp/o2r/compendium/KqPAH/.erc/package_slip.json
muncher_1         | 2018-04-26T09:17:08.758Z muncher:meta [KqPAH][zenodo_sandbox] [broker container] obj, end = self.raw_decode(s, idx=_w(s, 0).end())
muncher_1         |   File "/usr/local/lib/python3.6/json/decoder.py", line 357, in raw_decode
muncher_1         |     raise JSONDecodeError("Expecting value", s, err.value) from None
muncher_1         | json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
muncher_1         | 2018-04-26T09:17:09.279Z muncher:meta [KqPAH][zenodo] container running: Container { modem: Modem { socketPath: '/var/run/docker.sock', host: undefined, port: undefined, version: undefined, key: undefined, cert: undefined, ca: undefined, timeout: undefined, checkServerIdentity: undefined, protocol: 'http', Promise: [Function: Promise] }, id: '1597bbc475bb3c85b41ae59e240a99e76342e749b79d8743db06387f99c30038', defaultOptions: { top: {}, start: {}, commit: {}, stop: {}, pause: {}, unpause: {}, restart: {}, resize: {}, attach: {}, remove: {}, copy: {}, kill: {}, exec: {}, rename: {}, log: {}, stats: {}, getArchive: {}, infoArchive: {}, putArchive: {}, update: {} } }
muncher_1         | 2018-04-26T09:17:09.280Z muncher:meta [KqPAH][zenodo] Completed metadata brokering: { Error: null, StatusCode: 0 }
muncher_1         | 2018-04-26T09:17:09.280Z muncher:meta [KqPAH][zenodo] Completed metadata brokering and now have 6 metadata files: ["erc_spec.pdf","metadata_o2r_1.json","metadata_raw.json","metadata_zenodo_1.json","metadata_zenodo_sandbox_1.json","package_slip.json"]
muncher_1         | 2018-04-26T09:17:09.280Z muncher:meta [KqPAH] Loading brokering output from file /tmp/o2r/compendium/KqPAH/.erc/metadata_zenodo_1.json
muncher_1         | 2018-04-26T09:17:09.280Z muncher:meta [KqPAH][zenodo] Finished metadata brokering
muncher_1         | 2018-04-26T09:17:09.334Z muncher:meta [KqPAH][zenodo_sandbox] container running: Container { modem: Modem { socketPath: '/var/run/docker.sock', host: undefined, port: undefined, version: undefined, key: undefined, cert: undefined, ca: undefined, timeout: undefined, checkServerIdentity: undefined, protocol: 'http', Promise: [Function: Promise] }, id: 'fb45910f83f8d9afc961775076cf6b89a388a17bc822b7654972c2dde86d57a5', defaultOptions: { top: {}, start: {}, commit: {}, stop: {}, pause: {}, unpause: {}, restart: {}, resize: {}, attach: {}, remove: {}, copy: {}, kill: {}, exec: {}, rename: {}, log: {}, stats: {}, getArchive: {}, infoArchive: {}, putArchive: {}, update: {} } }
muncher_1         | 2018-04-26T09:17:09.334Z muncher:meta [KqPAH][zenodo_sandbox] Error during meta container run: { Error: null, StatusCode: 1 }
muncher_1         | 2018-04-26T09:17:09.335Z muncher:compendium [KqPAH] Problem during metadata brokering: Error: Received non-zero statuscode from container brokering metadata for zenodo_sandbox
muncher_1         | 2018-04-26T09:17:09.335Z muncher:compendium [KqPAH] Error during metadata update, returning error: { error: 'Error updating metadata file, see log for details' }
platform_1        | 172.19.0.1 - - [26/Apr/2018:09:17:09 +0000] "PUT /api/v1/compendium/KqPAH/metadata HTTP/1.1" 500 61 "-" "libcurl/7.47.0 r-curl/3.2 httr/1.3.1"
muncher_1         | 2018-04-26T09:17:09.337Z muncher:meta [KqPAH][zenodo_sandbox] Error getting container logs after non-zero status code

The package slip only contains o2r and zenodo, but lacks zenodo_sandbox:

daniel@gin-nuest:~$ sudo ls /var/lib/docker/volumes/o2rplatform_o2rstorage/_data/compendium/KqPAH/.erc/
erc_spec.pdf  metadata_o2r_1.json  metadata_raw.json  metadata_zenodo_1.json  metadata_zenodo_sandbox_1.json  package_slip.json
daniel@gin-nuest:~$ sudo cat /var/lib/docker/volumes/o2rplatform_o2rstorage/_data/compendium/KqPAH/.erc/package_slip.json
{
    "standards_used": [
        {
            "o2r": {
                "map_description": "maps raw extracted metadata to o2r schema compliant metadata",
                "mode": "json",
                "name": "o2r",
                "output_file_extension": ".json",
                "output_file_prefix": "metadata",
                "root": "",
                "version": "1"
            }
        },
        {
            "zenodo": {
                "map_description": "maps o2r schema compliant MD to Zenodo for deposition creation",
                "mode": "json",
                "name": "zenodo",
                "output_file_extension": ".json",
                "output_file_prefix": "metadata",
                "root": "metadata",
                "version": "1"
            }
        }
    ]
}

[nuest]

I might create a test to confirm this, until then here are some links for code that might handle this:

• https://codereview.stackexchange.com/questions/150139/thread-safe-file-operation
• https://stackoverflow.com/a/45764200/261210
• https://stackoverflow.com/questions/47712347/race-condition-when-multiple-processes-attempts-to-read-delete-files-in-the-sa
• https://stackoverflow.com/questions/3322011/is-this-method-of-file-locking-acceptable (using a lockfile could work)
• https://blog.gocept.com/2013/07/15/reliable-file-updates-with-python/ (code from "Consistency" looks promising approach)
  • https://docs.python.org/3/library/fcntl.html#module-fcntl
• https://pypi.org/project/filelock/
• http://tilde.town/~cristo/file-locking-in-python.html
• https://stackoverflow.com/a/34124007/261210
  • the recommended https://docs.openstack.org/oslo.concurrency/latest/user/index.html will probably not work because our function calls happen in two different containers

The bost solutions seems to be https://pypi.org/project/filelock/ (OS independent). We could just use a timeout, say 5 seconds, and then error. No need for loops or retries, the other operations should always complete within that time.