Access log query enhancements #815

hkethi002 · 2017-06-13T21:21:31Z

Fixes #811

Review Checklist

Tests were added to cover all code changes
Documentation was added / updated
Code and tests follow standards in CONTRIBUTING.mdRequirements:

Requirements:

Add ability to specify singular subject query param that only returns records where context.subject.label matches that input
Add ability to specify multiple access_type query params that only return records where access_type matches one of those inputs
Add csv query param that, when True, returns a csv file of all matching records flattened into rows
Write integration tests to thoroughly test the new functionality
Create new endpoint (/api/report/accesslog/types ?) that returns the available access types for frontend use.

nagem · 2017-06-21T19:30:40Z

Nice work, Harsha. I worry that this endpoint would tip over an instance if asked to create a CSV or return everything in a very large access_log. We'll have to discuss with @ryansanford what limitations for safety seem reasonable and the possibility of a command line tool to generate the CSV when you really do want to have millions of logs returned.

ryansanford · 2017-07-13T02:18:13Z

Somewhere between 70-80k results, we end up with the below error. That was indeed resolved by adding the index db.access_log.createIndex({timestamp: -1})

uwsgi_1           | 2017-07-13 02:01:26      scitran.api                  base.py   333:ERRO Traceback (most recent call last):
uwsgi_1           |   File "/usr/local/lib/python2.7/dist-packages/webapp2.py", line 570, in dispatch
uwsgi_1           |     return method(*args, **kwargs)
uwsgi_1           |   File "./api/handlers/reporthandler.py", line 77, in get
uwsgi_1           |     for doc in report.build():
uwsgi_1           |   File "./api/handlers/reporthandler.py", line 566, in build
uwsgi_1           |     return self.make_csv_ready(cursor)
uwsgi_1           |   File "./api/handlers/reporthandler.py", line 545, in make_csv_ready
uwsgi_1           |     return [self.flatten(json_obj, {}) for json_obj in cursor]
uwsgi_1           |   File "/usr/local/lib/python2.7/dist-packages/pymongo/cursor.py", line 1097, in next
uwsgi_1           |     if len(self.__data) or self._refresh():
uwsgi_1           |   File "/usr/local/lib/python2.7/dist-packages/pymongo/cursor.py", line 1019, in _refresh
uwsgi_1           |     self.__read_concern))
uwsgi_1           |   File "/usr/local/lib/python2.7/dist-packages/pymongo/cursor.py", line 905, in __send_message
uwsgi_1           |     helpers._check_command_response(doc['data'][0])
uwsgi_1           |   File "/usr/local/lib/python2.7/dist-packages/pymongo/helpers.py", line 196, in _check_command_response
uwsgi_1           |     raise OperationFailure(msg % errmsg, code, response)
uwsgi_1           | OperationFailure: Executor error during find command: OperationFailed: Sort operation used more than the maximum 33554432 bytes of RAM. Add an index, or specify a smaller limit.
uwsgi_1           |  request_id=c006d926-1499911285
uwsgi_1           | ./api/tempdir.py:42: Warning: start: Implicitly cleaning up <TemporaryDirectory u'/var/scitran/data/.tmpAdZzcl'>
uwsgi_1           |   Warning)
uwsgi_1           | ./api/tempdir.py:57: Warning: end: Implicitly cleaning up <TemporaryDirectory u'/var/scitran/data/.tmpAdZzcl'>
uwsgi_1           |   Warning)
uwsgi_1           | [pid: 46|app: 0|req: 27/121] 172.19.0.1 () {36 vars in 723 bytes} [Thu Jul 13 02:01:25 2017] GET /api/report/accesslog?user=ryansanford@flywheel.io&end_date=2017-07-11T00:00:00.000Z&start_date=2017-06-04T00:00:00.000Z&limit=80000&csv=true => generated 194 bytes in 557 msecs (HTTP/1.1 500) 3 headers in 131 bytes (2 switches on core 0)

ryansanford · 2017-07-13T02:27:25Z

Next breakage is happening between 300-400k. uwsgi worker is dying. This is happening after 17 seconds.

mongodb_1         | 2017-07-13T02:25:24.840+0000 I NETWORK  [initandlisten] connection accepted from 172.19.0.6:50080 #65 (14 connections now open)
mongodb_1         | 2017-07-13T02:25:24.848+0000 I NETWORK  [initandlisten] connection accepted from 172.19.0.6:50082 #66 (15 connections now open)
uwsgi_1           | 2017-07-13 02:25:24      scitran.api                  base.py   403:DEBU from ryansanford@flywheel.io GET /api/report/accesslog {u'csv': u'true', u'limit': u'400000', u'user': u'ryansanford@flywheel.io', u'end_date': u'2017-07-11T00:00:00.000Z', u'start_date': u'2017-06-04T00:00:00.000Z'} request_id=af740af3-1499912724
uwsgi_1           | 2017-07-13 02:25:24      scitran.api                config.py   223:INFO Initializing database, creating indexes
mongodb_1         | 2017-07-13T02:25:24.885+0000 I NETWORK  [initandlisten] connection accepted from 172.19.0.6:50084 #67 (16 connections now open)
mongodb_1         | 2017-07-13T02:25:24.888+0000 I NETWORK  [initandlisten] connection accepted from 172.19.0.6:50086 #68 (17 connections now open)
uwsgi_1           | 2017-07-13 02:25:24      scitran.api                config.py   255:INFO Persisting configuration
mongodb_1         | 2017-07-13T02:25:39.525+0000 I NETWORK  [conn66] end connection 172.19.0.6:50082 (16 connections now open)
mongodb_1         | 2017-07-13T02:25:39.525+0000 I NETWORK  [conn65] end connection 172.19.0.6:50080 (16 connections now open)
mongodb_1         | 2017-07-13T02:25:39.525+0000 I NETWORK  [conn67] end connection 172.19.0.6:50084 (16 connections now open)
mongodb_1         | 2017-07-13T02:25:39.525+0000 I NETWORK  [conn68] end connection 172.19.0.6:50086 (16 connections now open)
uwsgi_1           | DAMN ! worker 2 (pid: 100) died, killed by signal 9 :( trying respawn ...
uwsgi_1           | Respawned uWSGI worker 2 (new pid: 105)

ryansanford · 2017-07-13T02:37:25Z

@hkethi002 Would putting a python script in bin/ to handle arbitrary large exports make sense and be reliable, or would we have similar issue as uwsgi process dying as seen above?

ryansanford · 2017-07-13T02:53:11Z

Regarding the uwsgi exiting, it's due to running out of memory. It reaches about 2.5 GB at the point of processing 360k results

nagem · 2017-07-19T21:31:31Z

bin/database.py

+    """
+    Indexes the timestamps of access logs
+    """
+    config.log_db.access_log.createIndex({'timestamp': -1})


You can put this in config.py and it will get added on startup if it's not already there.

hkethi002 · 2017-07-20T19:44:18Z

Ran into Unicode Errors caused by some labels having emojis in them, and it seems like csv library being used uses ASCII so should they just be skipped for now?

nagem · 2017-07-20T21:48:37Z

We're going to have to support unicode, especially if we are going to support users whose languages don't use the ASCII char set. Looks like there is a unicode replacement for the csv lib:

https://github.com/jdunck/python-unicodecsv

nagem · 2017-07-27T17:58:49Z

api/handlers/reporthandler.py

            raise APIReportParamsException('Limit must be an integer greater than 0.')
+        for access_type in access_types:
+            if access_type not in AccessTypeList:
+                raise APIReportParamsException('Not a valid access type')


We should decide on a "safe" limit and reject requests that go over that limit. The rejection 400 could mention that an admin should run the script instead. @ryansanford what would you say the safe uwsgi log limit would be after your testing?

Then make sure we add a test for failing when attempting to go over that limit.

nagem · 2017-08-04T16:39:58Z

api/handlers/reporthandler.py

        if limit < 1:
            raise APIReportParamsException('Limit must be an integer greater than 0.')
+        elif limit > 10000:
+            raise APIReportParamsException('Limit exceeds 1000 entries, please contact admin to run script.')


Need one more zero on the error :)

nagem · 2017-08-04T16:40:46Z

After error message change, LGTM! Feel free to merge.

hkethi002 requested a review from nagem June 13, 2017 21:21

hkethi002 force-pushed the access-log-query branch 2 times, most recently from 6879e07 to 6eccabb Compare June 20, 2017 18:41

hkethi002 force-pushed the access-log-query branch from 6eccabb to 2a8057a Compare June 21, 2017 15:05

hkethi002 force-pushed the access-log-query branch from 2a8057a to 2cad0fd Compare June 26, 2017 14:10

hkethi002 force-pushed the access-log-query branch 3 times, most recently from 722c295 to 795d2c0 Compare July 3, 2017 17:37

ryansanford self-assigned this Jul 6, 2017

hkethi002 force-pushed the access-log-query branch from 795d2c0 to 6ff3ef7 Compare July 11, 2017 16:24

ryansanford assigned hkethi002 and unassigned ryansanford Jul 17, 2017

hkethi002 force-pushed the access-log-query branch 2 times, most recently from c4b0e03 to 66054cd Compare July 18, 2017 16:23

nagem reviewed Jul 19, 2017

View reviewed changes

hkethi002 force-pushed the access-log-query branch from cc4a208 to 9e1dc99 Compare July 20, 2017 15:13

hkethi002 force-pushed the access-log-query branch 2 times, most recently from d7ab4bd to 07de208 Compare July 25, 2017 16:35

nagem reviewed Jul 27, 2017

View reviewed changes

hkethi002 force-pushed the access-log-query branch from a20ff12 to 1eae317 Compare July 27, 2017 20:49

nagem requested a review from ryansanford July 31, 2017 16:17

hkethi002 force-pushed the access-log-query branch 2 times, most recently from 12a8976 to 52f6e63 Compare August 2, 2017 18:31

hkethi002 force-pushed the access-log-query branch from 52f6e63 to 21c33f0 Compare August 3, 2017 22:03

nagem reviewed Aug 4, 2017

View reviewed changes

hkethi002 force-pushed the access-log-query branch from 21c33f0 to dbd6da1 Compare August 4, 2017 18:42

hkethi002 added 9 commits August 4, 2017 13:44

subject and access_types params added

ff573ff

writes accesslog to csv file

a2636e7

csv file can be downloaded

7a5119c

tested new functionality of access log reports

6356e17

added endpoint for types

4925e1f

script to create large csv file started

53aa27d

fixed duplicate writes

52f3fad

using unicodecsv

8a35f92

limit for limit parameter

dbd6da1

hkethi002 merged commit febf00c into master Aug 4, 2017

hkethi002 deleted the access-log-query branch August 4, 2017 18:53

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Access log query enhancements #815

Access log query enhancements #815

Uh oh!

hkethi002 commented Jun 13, 2017 •

edited by nagem

Loading

Uh oh!

nagem commented Jun 21, 2017

Uh oh!

ryansanford commented Jul 13, 2017

Uh oh!

ryansanford commented Jul 13, 2017

Uh oh!

ryansanford commented Jul 13, 2017

Uh oh!

ryansanford commented Jul 13, 2017

Uh oh!

nagem Jul 19, 2017

Uh oh!

hkethi002 commented Jul 20, 2017

Uh oh!

nagem commented Jul 20, 2017

Uh oh!

nagem Jul 27, 2017

Uh oh!

nagem Jul 27, 2017

Uh oh!

nagem Aug 4, 2017

Uh oh!

nagem commented Aug 4, 2017

Uh oh!

Uh oh!

Access log query enhancements #815

Access log query enhancements #815

Uh oh!

Conversation

hkethi002 commented Jun 13, 2017 • edited by nagem Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Review Checklist

Uh oh!

nagem commented Jun 21, 2017

Uh oh!

ryansanford commented Jul 13, 2017

Uh oh!

ryansanford commented Jul 13, 2017

Uh oh!

ryansanford commented Jul 13, 2017

Uh oh!

ryansanford commented Jul 13, 2017

Uh oh!

nagem Jul 19, 2017

Choose a reason for hiding this comment

Uh oh!

hkethi002 commented Jul 20, 2017

Uh oh!

nagem commented Jul 20, 2017

Uh oh!

nagem Jul 27, 2017

Choose a reason for hiding this comment

Uh oh!

nagem Jul 27, 2017

Choose a reason for hiding this comment

Uh oh!

nagem Aug 4, 2017

Choose a reason for hiding this comment

Uh oh!

nagem commented Aug 4, 2017

Uh oh!

Uh oh!

hkethi002 commented Jun 13, 2017 •

edited by nagem

Loading