[BUG] Sporadic duplicate builtin process during startup

[fmigneault]

Error occurs sporadically and was seen during smoke tests, but most of the time (every PR) those tests seem to pass without issue. Source of the duplicate entries must be investigated. Most probably safe to ignore them completely.

full log here:
https://github.com/crim-ca/weaver/pull/244/checks?check_run_id=2462170973

smoke_test_weaver | [2021-04-28 23:02:24,246] INFO     [MainThread][weaver.app] Adding default caching options...
smoke_test_weaver | [2021-04-28 23:02:24,246] INFO     [MainThread][weaver.app] Setup celery configuration...
smoke_test_weaver | [2021-04-28 23:02:24,256] INFO     [MainThread][weaver] Adding Weaver
smoke_test_weaver | [2021-04-28 23:02:24,256] INFO     [MainThread][weaver.database] Adding database...
smoke_test_weaver | [2021-04-28 23:02:24,285] INFO     [MainThread][weaver.wps_restapi] Adding WPS REST API...
smoke_test_weaver | [2021-04-28 23:02:24,291] INFO     [MainThread][weaver.wps_restapi.jobs] Adding WPS REST API jobs...
smoke_test_weaver | [2021-04-28 23:02:24,298] INFO     [MainThread][weaver.wps_restapi.providers] Adding WPS REST API providers...
smoke_test_weaver | [2021-04-28 23:02:24,303] INFO     [MainThread][weaver.wps_restapi.processes] Adding WPS REST API processes...
smoke_test_weaver | [2021-04-28 23:02:24,309] INFO     [MainThread][weaver.wps_restapi.quotation] Adding WPS REST API quotation...
smoke_test_weaver | [2021-04-28 23:02:24,318] INFO     [MainThread][weaver.app] Registering builtin processes...
smoke_test_weaver | [2021-04-28 23:02:24,323] INFO     [MainThread][cwltool] Resolved '/tmp/tmp99zxrdjf/package' to 'file:///tmp/tmp99zxrdjf/package'
smoke_test_weaver | Resolved '/tmp/tmp99zxrdjf/package' to 'file:///tmp/tmp99zxrdjf/package'
smoke_test_weaver | [2021-04-28 23:02:25,149] INFO     [MainThread][cwltool] Resolved '/tmp/tmpu7ia9pjc/package' to 'file:///tmp/tmpu7ia9pjc/package'
smoke_test_weaver | Resolved '/tmp/tmpu7ia9pjc/package' to 'file:///tmp/tmpu7ia9pjc/package'
smoke_test_weaver | [2021-04-28 23:02:25,174] INFO     [MainThread][cwltool] Resolved '/tmp/tmpq64d1ha9/package' to 'file:///tmp/tmpq64d1ha9/package'
smoke_test_weaver | Resolved '/tmp/tmpq64d1ha9/package' to 'file:///tmp/tmpq64d1ha9/package'
smoke_test_weaver | Traceback (most recent call last):
smoke_test_weaver |   File "/usr/local/bin/pserve", line 8, in <module>
smoke_test_weaver |     sys.exit(main())
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/pyramid/scripts/pserve.py", line 30, in main
smoke_test_weaver |     return command.run()
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/pyramid/scripts/pserve.py", line 271, in run
smoke_test_weaver |     app = loader.get_wsgi_app(app_name, config_vars)
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/plaster_pastedeploy/__init__.py", line 129, in get_wsgi_app
smoke_test_weaver |     global_conf=defaults,
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/paste/deploy/loadwsgi.py", line 253, in loadapp
smoke_test_weaver |     return loadobj(APP, uri, name=name, **kw)
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/paste/deploy/loadwsgi.py", line 278, in loadobj
smoke_test_weaver |     return context.create()
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/paste/deploy/loadwsgi.py", line 715, in create
smoke_test_weaver |     return self.object_type.invoke(self)
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/paste/deploy/loadwsgi.py", line 152, in invoke
smoke_test_weaver |     return fix_call(context.object, context.global_conf, **context.local_conf)
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/paste/deploy/util.py", line 55, in fix_call
smoke_test_weaver |     val = callable(*args, **kw)
smoke_test_weaver |   File "/opt/local/src/weaver/weaver/__init__.py", line 20, in main
smoke_test_weaver |     return weaver.app.main(global_config, **settings)
smoke_test_weaver |   File "/opt/local/src/weaver/weaver/app.py", line 59, in main
smoke_test_weaver |     register_builtin_processes(local_config)
smoke_test_weaver |   File "/opt/local/src/weaver/weaver/processes/builtin/__init__.py", line 142, in register_builtin_processes
smoke_test_weaver |     get_db(container).get_store(StoreProcesses, default_processes=builtin_processes)
smoke_test_weaver |   File "/opt/local/src/weaver/weaver/database/mongodb.py", line 84, in get_store
smoke_test_weaver |     *store_args, **store_kwargs
smoke_test_weaver |   File "/opt/local/src/weaver/weaver/store/mongodb.py", line 191, in __init__
smoke_test_weaver |     self._register_defaults(default_processes)
smoke_test_weaver |   File "/opt/local/src/weaver/weaver/store/mongodb.py", line 219, in _register_defaults
smoke_test_weaver |     self._add_process(process)
smoke_test_weaver |   File "/opt/local/src/weaver/weaver/store/mongodb.py", line 237, in _add_process
smoke_test_weaver |     self.collection.insert_one(new_process.params())
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/pymongo/collection.py", line 701, in insert_one
smoke_test_weaver |     session=session),
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/pymongo/collection.py", line 615, in _insert
smoke_test_weaver |     bypass_doc_val, session)
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/pymongo/collection.py", line 603, in _insert_one
smoke_test_weaver |     acknowledged, _insert_command, session)
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/pymongo/mongo_client.py", line 1498, in _retryable_write
smoke_test_weaver |     return self._retry_with_session(retryable, func, s, None)
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/pymongo/mongo_client.py", line 1384, in _retry_with_session
smoke_test_weaver |     return self._retry_internal(retryable, func, session, bulk)
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/pymongo/mongo_client.py", line 1416, in _retry_internal
smoke_test_weaver |     return func(session, sock_info, retryable)
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/pymongo/collection.py", line 600, in _insert_command
smoke_test_weaver |     _check_write_command_response(result)
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/pymongo/helpers.py", line 226, in _check_write_command_response
smoke_test_weaver |     _raise_last_write_error(write_errors)
smoke_test_weaver |   File "/usr/local/lib/python3.7/site-packages/pymongo/helpers.py", line 207, in _raise_last_write_error
smoke_test_weaver |     raise DuplicateKeyError(error.get("errmsg"), 11000, error)
smoke_test_weaver | pymongo.errors.DuplicateKeyError: E11000 duplicate key error collection: weaver.processes index: identifier_1 dup key: { : "file2string_array" }, full error: {'index': 0, 'code': 11000, 'errmsg': 'E11000 duplicate key error collection: weaver.processes index: identifier_1 dup key: { : "file2string_array" }'}
smoke_test_worker | [2021-04-28 23:02:24,163] INFO     [weaver.app] Initiating weaver application
smoke_test_worker | [2021-04-28 23:02:24,163] INFO     [weaver.app] Parsing extra options...
smoke_test_worker | [2021-04-28 23:02:24,163] INFO     [weaver.app] Checking for request options file...
smoke_test_worker | [2021-04-28 23:02:24,164] WARNING  [weaver.config] Cannot find configuration file: [/opt/local/src/weaver/config/request_options.yml]. Falling back to default.
smoke_test_worker | [2021-04-28 23:02:24,164] WARNING  [weaver.config] Could not find default configuration file: [/opt/local/src/weaver/config/request_options.yml]. 
smoke_test_worker | [2021-04-28 23:02:24,164] WARNING  [weaver.config] Default file generation from default disabled. No file returned.
smoke_test_worker | [2021-04-28 23:02:24,165] WARNING  [weaver.app] No request options found.
smoke_test_worker | [2021-04-28 23:02:24,165] INFO     [weaver.app] Adding default caching options...
smoke_test_worker | [2021-04-28 23:02:24,165] INFO     [weaver.app] Setup celery configuration...
smoke_test_worker | [2021-04-28 23:02:24,176] INFO     [weaver] Adding Weaver
smoke_test_worker | [2021-04-28 23:02:24,176] INFO     [weaver.database] Adding database...
smoke_test_worker | [2021-04-28 23:02:24,209] INFO     [weaver.wps_restapi] Adding WPS REST API...
smoke_test_worker | [2021-04-28 23:02:24,216] INFO     [weaver.wps_restapi.jobs] Adding WPS REST API jobs...
smoke_test_worker | [2021-04-28 23:02:24,223] INFO     [weaver.wps_restapi.providers] Adding WPS REST API providers...
smoke_test_worker | [2021-04-28 23:02:24,228] INFO     [weaver.wps_restapi.processes] Adding WPS REST API processes...
smoke_test_worker | [2021-04-28 23:02:24,235] INFO     [weaver.wps_restapi.quotation] Adding WPS REST API quotation...
smoke_test_worker | [2021-04-28 23:02:24,245] INFO     [weaver.app] Registering builtin processes...
smoke_test_worker | Resolved '/tmp/tmp326dsj8z/package' to 'file:///tmp/tmp326dsj8z/package'
smoke_test_worker | Resolved '/tmp/tmpk9n9qjba/package' to 'file:///tmp/tmpk9n9qjba/package'
smoke_test_worker | Resolved '/tmp/tmptje78a_l/package' to 'file:///tmp/tmptje78a_l/package'
smoke_test_worker | [2021-04-28 23:02:25,216] INFO     [weaver.app] Registering WPS-1 processes from configuration file...
smoke_test_worker | [2021-04-28 23:02:25,216] WARNING  [weaver.config] Cannot find configuration file: [/opt/local/src/weaver/config/wps_processes.yml]. Falling back to default.
smoke_test_worker | [2021-04-28 23:02:25,216] WARNING  [weaver.config] Could not find default configuration file: [/opt/local/src/weaver/config/wps_processes.yml]. 
smoke_test_worker | [2021-04-28 23:02:25,216] WARNING  [weaver.config] Default file generation from default disabled. No file returned.
smoke_test_worker |  
smoke_test_worker |  -------------- celery@57234d21446d v4.4.2 (cliffs)
smoke_test_worker | --- ***** ----- 
smoke_test_worker | -- ******* ---- Linux-5.4.0-1046-azure-x86_64-with-debian-10.9 2021-04-28 23:02:25
smoke_test_worker | - *** --- * --- 
smoke_test_worker | - ** ---------- [config]
smoke_test_worker | - ** ---------- .> app:         __main__:0x7f330e187f50
smoke_test_worker | - ** ---------- .> transport:   mongodb://mongodb:27017/celery
smoke_test_worker | - ** ---------- .> results:     disabled://
smoke_test_worker | - *** --- * --- .> concurrency: 2 (prefork)
smoke_test_worker | -- ******* ---- .> task events: OFF (enable -E to monitor tasks in this worker)
smoke_test_worker | --- ***** ----- 
smoke_test_worker |  -------------- [queues]
smoke_test_worker |                 .> celery           exchange=celery(direct) key=celery
smoke_test_worker |                 
smoke_test_worker | 
smoke_test_worker | [2021-04-28 23:02:25,550] INFO     [MainThread][celery.worker.consumer.connection] Connected to mongodb://mongodb:27017/celery
smoke_test_worker | [2021-04-28 23:02:25,581] INFO     [MainThread][celery.apps.worker] celery@57234d21446d ready.
Stopping smoke_test_worker  ... 
Stopping smoke_test_mongodb ... 
Stopping smoke_test_worker  ... done
Stopping smoke_test_mongodb ... done
make: *** [Makefile:600: docker-test] Error 1
Error: Process completed with exit code 2.