Add logging to the API server

[rzats]

Closes #1002.

Prerequisites:

• Unless it is a documentation hotfix it should be merged against the dev branch
• Branch is up-to-date with the branch to be merged with, i.e. dev
• Build is successful
• Code is cleaned up and formatted

Summary

Adds far more extra logging statements to the Covidcast server code. This includes:

• Flask hooks that log and time every API request
• Flask hooks that time every SQL query (cherry-picked from add logging of query timing for elasticsearch and such. #757, thanks @melange396!)
• Logging for every validation exception in the server
• Logging for some edge cases and exceptions (work-in-progress)
• Logging for datetime optimization added in Use BETWEEN queries in the API as much as possible #977, Add IDE bindings for epidata development #1004, and Code improvements to time processing routines #1010

Suggestions for other code paths or metrics that can be logged are welcome and encourage :)

[melange396]

great start. i havent gotten to the changes in dates.py yet but i will soon.

[melange396]

it looks like a typical successful request will have ~4 log emissions, right?

• those messages appear to include:

  • 1 pre-request message
  • 1 post-request message
  • 1+ [probable] sql execute message(s)
  • 1 date range adjustment message [ & 1 more when guessing day/week (really only happens in wiki.py and twitter.py endpoints) ]
  • 0-1 potential validation failure message
  • 0+ potential more serious error message

• we can also tune some log levels:

  • ValidationException messages should be info- or warn-level instead of error
  • most of the stuff in dates.py can be debug-level (the one should stay error, though)
  • if we also make sure the prod webserver logs @ info and the dev environment logs @ debug, itll take 25% off of the message counts in elastic.

[melange396]

i think these last few changes will about do it for this pr!

can you provide us with sample log outputs to compare what they look like before and after this pr? maybe do one with the logs emitted when processing a request to the covidcast endpoint, and then one from some other endpoint?

[rzats]

@melange396

can you provide us with sample log outputs to compare what they look like before and after this pr? maybe do one with the logs emitted when processing a request to the covidcast endpoint, and then one from some other endpoint?

covidcast logs, before PR:

[2022-11-29 07:52:00 -0500] [10] [INFO] full_query: SELECT t.geo_value, t.signal, t.time_value, t.direction, t.issue, t.lag, t.missing_value, t.missing_stderr, t.missing_sample_size, t.value, t.stderr, t.sample_size FROM epimetric_latest_v t   WHERE ((t.source = :source_0t AND (t.signal = :source_0t_0))) AND (t.geo_type = :geo_type_0t) AND ((t.time_type = :time_type_0t AND (t.time_value = :time_type_0t_0)))  ORDER BY t.signal ASC, t.time_value ASC, t.geo_value ASC, t.issue ASC LIMIT 3651, params: {'source_0t': 'src-name', 'source_0t_0': 'test', 'geo_type_0t': 'state', 'time_type_0t': 'day', 'time_type_0t_0': 20200419}
[2022-11-29 07:52:00 -0500] [10] [INFO] SELECT t.geo_value, t.signal, t.time_value, t.direction, t.issue, t.lag, t.missing_value, t.missing_stderr, t.missing_sample_size, t.value, t.stderr, t.sample_size FROM epimetric_latest_v t   WHERE ((t.source = %s AND (t.signal = %s))) AND (t.geo_type = %s) AND ((t.time_type = %s AND (t.time_value = %s)))  ORDER BY t.signal ASC, t.time_value ASC, t.geo_value ASC, t.issue ASC LIMIT 3651
[2022-11-29 07:52:00 -0500] [10] [INFO] [generated in 0.00021s] ('src-name', 'test', 'state', 'day', 20200419)
172.18.0.4 - - [29/Nov/2022:07:52:00 -0500] "GET /epidata/api.php HTTP/1.1" 200 669 "-" "delphi_epidata/0.4.1"
172.18.0.4 - - [29/Nov/2022:07:52:00 -0500] "- - HTTP/1.0" 0 0 "-" "-"

covidcast logs, after PR:

{"method": "GET", "url": "http://delphi_web_epidata/epidata/api.php?endpoint=covidcast&data_source=src-name&signals=test&time_type=day&geo_type=state&time_values=20200419&geo_value=*", "form_args": {}, "req_length": null, "remote_addr": "172.18.0.4", "user_agent": "delphi_epidata/0.4.1", "event": "Received API request", "logger": "server_api", "level": "info", "pid": 13, "timestamp": "2022-11-29T12:43:25.601325Z"}
{"original": [20200419], "optimized": [20200419], "original_length": 1, "optimized_length": 1, "event": "Optimized list of date values", "logger": "server_utils", "level": "info", "pid": 13, "timestamp": "2022-11-29T12:43:25.602127Z"}
{"statement": "SELECT t.geo_value, t.signal, t.time_value, t.direction, t.issue, t.lag, t.missing_value, t.missing_stderr, t.missing_sample_size, t.value, t.stderr, t.sample_size FROM epimetric_latest_v t   WHERE ((t.source = %s AND (t.signal = %s))) AND (t.geo_type = %s) AND ((t.time_type = %s AND (t.time_value = %s)))  ORDER BY t.signal ASC, t.time_value ASC, t.geo_value ASC, t.issue ASC LIMIT 3651", "params": ["src-name", "test", "state", "day", 20200419], "elapsed_time_ms": 0.7178783416748047, "event": "Executed SQL", "logger": "server_api", "level": "info", "pid": 13, "timestamp": "2022-11-29T12:43:25.603607Z"}
{"method": "GET", "url": "http://delphi_web_epidata/epidata/api.php?endpoint=covidcast&data_source=src-name&signals=test&time_type=day&geo_type=state&time_values=20200419&geo_value=*", "form_args": {}, "req_length": null, "remote_addr": "172.18.0.4", "user_agent": "delphi_epidata/0.4.1", "values": {"endpoint": ["covidcast"], "data_source": ["src-name"], "signals": ["test"], "time_type": ["day"], "geo_type": ["state"], "time_values": ["20200419"], "geo_value": ["*"]}, "blueprint": null, "endpoint": "handle_generic", "response_status": "200 OK", "content_length": 669, "elapsed_time_ms": 2.9630661010742188, "event": "Served API request", "logger": "server_api", "level": "info", "pid": 13, "timestamp": "2022-11-29T12:43:25.604323Z"}
172.18.0.4 - - [29/Nov/2022:07:43:25 -0500] "GET /epidata/api.php HTTP/1.1" 200 669 "-" "delphi_epidata/0.4.1"
172.18.0.4 - - [29/Nov/2022:07:43:25 -0500] "- - HTTP/1.0" 0 0 "-" "-"

fluview_meta logs, before PR:

[2022-11-29 07:52:05 -0500] [10] [INFO] SELECT max(`release_date`) `latest_update`, max(`issue`) `latest_issue`, count(1) `table_rows` FROM `fluview`
INFO:sqlalchemy.engine.Engine:SELECT max(`release_date`) `latest_update`, max(`issue`) `latest_issue`, count(1) `table_rows` FROM `fluview`
[2022-11-29 07:52:05 -0500] [10] [INFO] [generated in 0.00021s] ()
INFO:sqlalchemy.engine.Engine:[generated in 0.00021s] ()
172.18.0.4 - - [29/Nov/2022:07:52:05 -0500] "GET /epidata/api.php HTTP/1.1" 200 119 "-" "delphi_epidata/0.4.1"
172.18.0.4 - - [29/Nov/2022:07:52:05 -0500] "- - HTTP/1.0" 0 0 "-" "-"

fluview_meta logs, after PR:

{"method": "GET", "url": "http://delphi_web_epidata/epidata/api.php?endpoint=fluview_meta", "form_args": {}, "req_length": null, "remote_addr": "172.18.0.4", "user_agent": "delphi_epidata/0.4.1", "event": "Received API request", "logger": "server_api", "level": "info", "pid": 13, "timestamp": "2022-11-29T12:43:31.168299Z"}
{"statement": "SELECT max(`release_date`) `latest_update`, max(`issue`) `latest_issue`, count(1) `table_rows` FROM `fluview`", "params": [], "elapsed_time_ms": 0.9546279907226562, "event": "Executed SQL", "logger": "server_api", "level": "info", "pid": 13, "timestamp": "2022-11-29T12:43:31.170272Z"}
{"method": "GET", "url": "http://delphi_web_epidata/epidata/api.php?endpoint=fluview_meta", "form_args": {}, "req_length": null, "remote_addr": "172.18.0.4", "user_agent": "delphi_epidata/0.4.1", "values": {"endpoint": ["fluview_meta"]}, "blueprint": null, "endpoint": "handle_generic", "response_status": "200 OK", "content_length": 119, "elapsed_time_ms": 0.9679794311523438, "event": "Served API request", "logger": "server_api", "level": "info", "pid": 13, "timestamp": "2022-11-29T12:43:31.170640Z"}
172.18.0.4 - - [29/Nov/2022:07:43:31 -0500] "GET /epidata/api.php HTTP/1.1" 200 119 "-" "delphi_epidata/0.4.1"
172.18.0.4 - - [29/Nov/2022:07:43:31 -0500] "- - HTTP/1.0" 0 0 "-"

[krivard]

@melange396 dates.py logs are still at INFO level, not DEBUG. is that intentional?

[melange396]

dates.py logs are still at INFO level, not DEBUG. is that intentional?

@krivard - Rostyslav wanted to see the output of them in production, so we agreed to leave them INFO for some period of time. as soon as this pr gets merged, i will create an issue to turn them down.

[krivard]

🚀 Nice work!

[melange396]

well done!