logging error: no such table pywps_requests

[bstdenis]

Description

Commit https://github.com/geopython/pywps/commit/418c92e6d203c547560395333696d1a60a3ce05e reintroduced the intermittant

[Fri Mar 24 17:10:56.955248 2017] [wsgi:error] [pid 23:tid 140223196669696] [remote 172.17.0.1:60489] File "/usr/local/lib/python2.7/dist-packages/pywps-4.0.0-py2.7.egg/pywps/dblog.py", line 76, in log_request [Fri Mar 24 17:10:56.955383 2017] [wsgi:error] [pid 23:tid 140223196669696] [remote 172.17.0.1:60489] session.commit() ... OperationalError: (sqlite3.OperationalError) no such table: pywps_requests

problem. That is to say, I can launch a process a couple of times, then I will get a 500 Internal Server Error once in a while. This is triggered in various places when pywps calls update_response() or log_request() or session.count().

To fix the problem presently, I have to force get_session to not use the _SESSION_MAKER (i.e., I commented out the following lines in dblog.py):

#if _SESSION_MAKER:
#    _SESSION_MAKER.close_all()
#    _LAST_SESSION = _SESSION_MAKER()
#    return _LAST_SESSION

This issue does not arise if I revert back to commit https://github.com/geopython/pywps/commit/77bc4ec0a39b8424b503a31c355726cd63ec91a5

Environment

• operating system: Ubuntu 16.04
• Python version: 2.7.12
• PyWPS version: 4.0.0 (2017-01-31)
• source/distribution
  • [x] git clone
  • [ ] Debian
  • [ ] PyPI
  • [ ] zip/tar.gz
  • [ ] other (please specify):
• web server
  • [x] Apache/mod_wsgi
  • [ ] CGI
  • [ ] other (please specify):

Steps to Reproduce

Additional Information

[jachym]

Thanks for the report. Btw - does it crash only for async requests or also for sync requests?

[bstdenis]

I confirm that it's for both sync and async processes. It happens roughly every other call, and it does not matter whether the calls are really close together in time, or if I wait a while before making another call.

[cehbrecht]

@bstdenis Is this still an open issue? I haven't validated or experienced it by myself. It needs to be checked and I will add it to our project tasks (dar-es-salaam).

@elemoine Do you have a comment for this bug report?

[bstdenis]

Yes, I still have this intermittent failure in the latest develop if I use the in memory sqlite database, i.e.: [logging] database=sqlite:// However I no longer get the 500 Internal Server Error, instead, WPS returns:

<!-- PyWPS 4.0.0 -->
<ows:ExceptionReport xmlns:ows="http://www.opengis.net/ows/1.1" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="http://www.opengis.net/ows/1.1 http://schemas.opengis.net/ows/1.1.0/owsExceptionReport.xsd" version="1.0.0">
  <ows:Exception exceptionCode="NoApplicableCode" locator="" >
      <ows:ExceptionText>No applicable error code, please check error log</ows:ExceptionText>
  </ows:Exception>
</ows:ExceptionReport>

The apache2 error.log is not helping me much, sqlalchemy is giving a lot of INFO level logging, on successful calls, it starts with:

[Thu Mar 22 18:25:11.507591 2018] [wsgi:error] [pid 24:tid 140211920979712] 2018-03-22 18:25:11,507 INFO sqlalchemy.engine.base.Engine BEGIN (implicit)
[Thu Mar 22 18:25:11.508908 2018] [wsgi:error] [pid 24:tid 140211920979712] 2018-03-22 18:25:11,508 INFO sqlalchemy.engine.base.Engine INSERT INTO pywps_requests (uuid, pid, operation, version, time_start, time_end, identifier, message, percent_done, status) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
[Thu Mar 22 18:25:11.509115 2018] [wsgi:error] [pid 24:tid 140211920979712] 2018-03-22 18:25:11,508 INFO sqlalchemy.engine.base.Engine ('5b830a9c-2dfe-11e8-a329-0242ac110002', 24, u'execute', u'1.0.0', '2018-03-22 18:25:11.506255', None, u'sync', None, None, None)
[Thu Mar 22 18:25:11.509827 2018] [wsgi:error] [pid 24:tid 140211920979712] 2018-03-22 18:25:11,509 INFO sqlalchemy.engine.base.Engine COMMIT
[Thu Mar 22 18:25:11.515047 2018] [wsgi:error] [pid 24:tid 140211920979712] 2018-03-22 18:25:11,514 INFO sqlalchemy.engine.base.Engine BEGIN (implicit)
[Thu Mar 22 18:25:11.516053 2018] [wsgi:error] [pid 24:tid 140211920979712] 2018-03-22 18:25:11,515 INFO sqlalchemy.engine.base.Engine SELECT count(*) AS count_1
...

On failed calls, it goes:

[Thu Mar 22 18:25:13.502522 2018] [wsgi:error] [pid 24:tid 140211929372416] 2018-03-22 18:25:13,502 INFO sqlalchemy.engine.base.Engine BEGIN (implicit)
[Thu Mar 22 18:25:13.502915 2018] [wsgi:error] [pid 24:tid 140211929372416] 2018-03-22 18:25:13,502 INFO sqlalchemy.engine.base.Engine INSERT INTO pywps_requests (uuid, pid, operation, version, time_start, time_end, identifier, message, percent_done, status) VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?)
[Thu Mar 22 18:25:13.503093 2018] [wsgi:error] [pid 24:tid 140211929372416] 2018-03-22 18:25:13,502 INFO sqlalchemy.engine.base.Engine ('5cb38464-2dfe-11e8-9d39-0242ac110002', 24, u'execute', u'1.0.0', '2018-03-22 18:25:13.501562', None, u'sync', None, None, None)
[Thu Mar 22 18:25:13.503360 2018] [wsgi:error] [pid 24:tid 140211929372416] 2018-03-22 18:25:13,503 INFO sqlalchemy.engine.base.Engine ROLLBACK

Then stops, not sure what's going on. I don't have this problem with an actual sqlite file (i.e. database=sqlite:///pywpslog.db) or a postgresql logging database. So at this point I guess it's an sqlalchemy problem.

[cehbrecht]

@bstdenis Thanks for testing it again.

If it only fails for the memory database then it is a low-priority bug. I use sqlite for development and for production we need to use postgres db.