[ckan-dev] Stuck DataPusher / DataStore job

• Previous message: [ckan-dev] ckan-dev Digest, Vol 86, Issue 11
• Next message: [ckan-dev] Stuck DataPusher / DataStore job
• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]

Hi everybody,

after manually changing the title of a resource in my CKAN 2.7 instance I 
ended up with a stuck DataPusher / DataStore job for that resource's CSV 
file: if I edit the resource and check the "DataStore" tab then it tells 
me that the resource is still being uploaded to the DataStore. This has 
been going on for more than 30 minutes, while the CSV file is rather small 
(17KB, around 450 records).

I tried re-submitting the job by editing the resource again manually (this 
did not change anything or reset the job's timer) and by using paster. The 
latter also failed:

-----
paster --plugin=ckan datapusher submit 
6dfd8a0c-019f-401c-82b6-4f808e31f7f9 -c /etc/ckan/default/production.ini 
Data in any datastore resource that isn't in their source files (e.g. data 
added using the datastore API) will be permanently lost. Are you sure you 
want to proceed? [y/n] y
Submitting 1 datastore resources
Submitting 15e317b3-0e17-4451-9d4e-5d5478620f1c... Fail
-----

Querying the resource's datastore entry via the datastore_info API 
function works as expected.

I tried to figure out what's going wrong, but the DataPusher's 
documentation and its debugging options seem to be limited (any pointers 
are very welcome!). In the log files I found the following:

-----
[Tue Jan 09 08:15:03.544059 2018] [wsgi:error] [pid 9913] 
/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/sql/sqltypes.py:219: 
SAWarning: Unicode type received non-unicode bind param value 
'9b75e6b9-59a5-4b8b-9a93-1...'. (this warning may be suppressed after 10 
occurrences)
[Tue Jan 09 08:15:03.544114 2018] [wsgi:error] [pid 9913] 
(util.ellipses_string(value),))
[Tue Jan 09 08:15:13.892433 2018] [wsgi:error] [pid 9913] Error notifying 
listener
[Tue Jan 09 08:15:13.892464 2018] [wsgi:error] [pid 9913] Traceback (most 
recent call last):
[Tue Jan 09 08:15:13.892468 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/apscheduler/scheduler.py", 
line 239, in _notify_listeners
[Tue Jan 09 08:15:13.892471 2018] [wsgi:error] [pid 9913]     cb(event)
[Tue Jan 09 08:15:13.892473 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/ckanserviceprovider/web.py", 
line 184, in job_listener
[Tue Jan 09 08:15:13.892476 2018] [wsgi:error] [pid 9913] 
db.mark_job_as_errored(job_id, error_object)
[Tue Jan 09 08:15:13.892479 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/ckanserviceprovider/db.py", 
line 413, in mark_job_as_errored
[Tue Jan 09 08:15:13.892482 2018] [wsgi:error] [pid 9913] 
_update_job(job_id, update_dict)
[Tue Jan 09 08:15:13.892484 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/ckanserviceprovider/db.py", 
line 361, in _update_job
[Tue Jan 09 08:15:13.892487 2018] [wsgi:error] [pid 9913] 
.values(**job_dict))
[Tue Jan 09 08:15:13.892489 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 2064, in execute
[Tue Jan 09 08:15:13.892492 2018] [wsgi:error] [pid 9913]     return 
connection.execute(statement, *multiparams, **params)
[Tue Jan 09 08:15:13.892495 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 945, in execute
[Tue Jan 09 08:15:13.892497 2018] [wsgi:error] [pid 9913]     return 
meth(self, multiparams, params)
[Tue Jan 09 08:15:13.892500 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", 
line 263, in _execute_on_connection
[Tue Jan 09 08:15:13.892503 2018] [wsgi:error] [pid 9913]     return 
connection._execute_clauseelement(self, multiparams, params)
[Tue Jan 09 08:15:13.892506 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 1053, in _execute_clauseelement
[Tue Jan 09 08:15:13.892508 2018] [wsgi:error] [pid 9913] compiled_sql, 
distilled_params
[Tue Jan 09 08:15:13.892511 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 1209, in _execute_context
[Tue Jan 09 08:15:13.892514 2018] [wsgi:error] [pid 9913] 
self._root._commit_impl(autocommit=True)
[Tue Jan 09 08:15:13.892516 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 726, in _commit_impl
[Tue Jan 09 08:15:13.892519 2018] [wsgi:error] [pid 9913] 
self.connection._reset_agent is self.__transaction:
[Tue Jan 09 08:15:13.892521 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 351, in connection
[Tue Jan 09 08:15:13.892524 2018] [wsgi:error] [pid 9913] 
self._handle_dbapi_exception(e, None, None, None, None)
[Tue Jan 09 08:15:13.892527 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 1405, in _handle_dbapi_exception
[Tue Jan 09 08:15:13.892529 2018] [wsgi:error] [pid 9913] 
util.reraise(*exc_info)
[Tue Jan 09 08:15:13.892532 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 349, in connection
[Tue Jan 09 08:15:13.892534 2018] [wsgi:error] [pid 9913]     return 
self._revalidate_connection()
[Tue Jan 09 08:15:13.892555 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 429, in _revalidate_connection
[Tue Jan 09 08:15:13.892558 2018] [wsgi:error] [pid 9913]     raise 
exc.ResourceClosedError("This Connection is closed")
[Tue Jan 09 08:15:13.892561 2018] [wsgi:error] [pid 9913] 
ResourceClosedError: This Connection is closed
[Tue Jan 09 08:15:13.911894 2018] [wsgi:error] [pid 9913] Job 
"push_to_datastore (trigger: RunTriggerNow, run = True, next run at: 
None)" raised an exception
[Tue Jan 09 08:15:13.911906 2018] [wsgi:error] [pid 9913] Traceback (most 
recent call last):
[Tue Jan 09 08:15:13.911909 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/apscheduler/scheduler.py", 
line 512, in _run_job
[Tue Jan 09 08:15:13.911912 2018] [wsgi:error] [pid 9913]     retval = 
job.func(*job.args, **job.kwargs)
[Tue Jan 09 08:15:13.911914 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/src/datapusher/datapusher/jobs.py", line 307, in 
push_to_datastore
[Tue Jan 09 08:15:13.911917 2018] [wsgi:error] [pid 9913] 
logger.info('Fetching from: {0}'.format(resource.get('url')))
[Tue Jan 09 08:15:13.911920 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/python2.7/logging/__init__.py", line 1160, in info
[Tue Jan 09 08:15:13.911923 2018] [wsgi:error] [pid 9913] self._log(INFO, 
msg, args, **kwargs)
[Tue Jan 09 08:15:13.911925 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/python2.7/logging/__init__.py", line 1279, in _log
[Tue Jan 09 08:15:13.911928 2018] [wsgi:error] [pid 9913] 
self.handle(record)
[Tue Jan 09 08:15:13.911930 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/python2.7/logging/__init__.py", line 1289, in handle
[Tue Jan 09 08:15:13.911933 2018] [wsgi:error] [pid 9913] 
self.callHandlers(record)
[Tue Jan 09 08:15:13.911935 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/python2.7/logging/__init__.py", line 1329, in callHandlers
[Tue Jan 09 08:15:13.911938 2018] [wsgi:error] [pid 9913] 
hdlr.handle(record)
[Tue Jan 09 08:15:13.911940 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/python2.7/logging/__init__.py", line 757, in handle
[Tue Jan 09 08:15:13.911943 2018] [wsgi:error] [pid 9913] 
self.emit(record)
[Tue Jan 09 08:15:13.911945 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/ckanserviceprovider/util.py", 
line 58, in emit
[Tue Jan 09 08:15:13.911948 2018] [wsgi:error] [pid 9913] 
lineno=record.lineno))
[Tue Jan 09 08:15:13.911951 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 945, in execute
[Tue Jan 09 08:15:13.911953 2018] [wsgi:error] [pid 9913]     return 
meth(self, multiparams, params)
[Tue Jan 09 08:15:13.911956 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/sql/elements.py", 
line 263, in _execute_on_connection
[Tue Jan 09 08:15:13.911959 2018] [wsgi:error] [pid 9913]     return 
connection._execute_clauseelement(self, multiparams, params)
[Tue Jan 09 08:15:13.911961 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 1053, in _execute_clauseelement
[Tue Jan 09 08:15:13.911964 2018] [wsgi:error] [pid 9913] compiled_sql, 
distilled_params
[Tue Jan 09 08:15:13.911967 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 1209, in _execute_context
[Tue Jan 09 08:15:13.911969 2018] [wsgi:error] [pid 9913] 
self._root._commit_impl(autocommit=True)
[Tue Jan 09 08:15:13.911972 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 723, in _commit_impl
[Tue Jan 09 08:15:13.911974 2018] [wsgi:error] [pid 9913] 
self._handle_dbapi_exception(e, None, None, None, None)
[Tue Jan 09 08:15:13.911977 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 1402, in _handle_dbapi_exception
[Tue Jan 09 08:15:13.911989 2018] [wsgi:error] [pid 9913]     exc_info
[Tue Jan 09 08:15:13.911992 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/util/compat.py", 
line 203, in raise_from_cause
[Tue Jan 09 08:15:13.911995 2018] [wsgi:error] [pid 9913] 
reraise(type(exception), exception, tb=exc_tb, cause=cause)
[Tue Jan 09 08:15:13.911997 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/base.py", 
line 721, in _commit_impl
[Tue Jan 09 08:15:13.912000 2018] [wsgi:error] [pid 9913] 
self.engine.dialect.do_commit(self.connection)
[Tue Jan 09 08:15:13.912002 2018] [wsgi:error] [pid 9913]   File 
"/usr/lib/ckan/datapusher/lib/python2.7/site-packages/sqlalchemy/engine/default.py", 
line 443, in do_commit
[Tue Jan 09 08:15:13.912005 2018] [wsgi:error] [pid 9913] 
dbapi_connection.commit()
[Tue Jan 09 08:15:13.912008 2018] [wsgi:error] [pid 9913] 
OperationalError: (sqlite3.OperationalError) database is locked
-----

The timestamps of these messages match the time that I've updated the 
resource, so I'm assuming that these belong to the stuck job. I don't know 
enough about the DataStore / DataPusher internals to really understand 
what's going on.

How can I resubmit that job so that the resource data is successfully 
uploaded to the DataStore?


Best regards,
Florian
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.okfn.org/pipermail/ckan-dev/attachments/20180109/502c7865/attachment-0002.html>

• Previous message: [ckan-dev] ckan-dev Digest, Vol 86, Issue 11
• Next message: [ckan-dev] Stuck DataPusher / DataStore job
• Messages sorted by: [ date ] [ thread ] [ subject ] [ author ]