-
Notifications
You must be signed in to change notification settings - Fork 50
Add logging and fix all logging contexts #790
Conversation
API Developer Docs Preview: Ready https://wordpress.github.io/openverse-api/_preview/790 Please note that GitHub pages takes a little time to deploy newly pushed code, if the links above don't work or you see old versions, wait 5 minutes and try again. You can check the GitHub pages deployment action list to see the current status of the deployments. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
This is going to be so helpful ✨ The inclusion of the new doc is fantastic, and the approach here with the logging context is also a major improvement.
I tested a few endpoints to try to generate and verify as many of the logs as I could, except the audio waveforms. I only encountered the one error when searching by source
.
|
||
# TODO: What does this request_size mean vs the one below | ||
# that doesn't subtract 1 from the page? Why do we subtract | ||
# 1 here and the other time we do not? |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
The refactoring here looks good to me in that it preserves the original logic, but I agree that I am also confused 😄 Excited to have the logs to allow for investigation.
This looks really nice! Here's some example output for the following local query:
[2022-07-07 14:16:39,417 - catalog.api.controllers.elasticsearch.search.perform_search - 117][INFO] [0c877f0718634f78b45f6ed8437eb3bb] searching with query_serializer.data={"source": "", "filter_dead": true, "mature": false, "qa": false, "page": 1, "page_size": 20} index=image (hashed) ip=6653667704586267427
[2022-07-07 14:16:39,431 - catalog.api.controllers.elasticsearch.utils.exclude_filtered_providers - 47][INFO] [0c877f0718634f78b45f6ed8437eb3bb] filtered_providers=
[2022-07-07 14:16:39,432 - catalog.api.controllers.elasticsearch.search.perform_search - 176][INFO] [0c877f0718634f78b45f6ed8437eb3bb] searching without query term
[2022-07-07 14:16:39,434 - catalog.api.controllers.elasticsearch.utils.get_query_slice - 161][INFO] [0c877f0718634f78b45f6ed8437eb3bb] start_slice=0 end_slice=40
[2022-07-07 14:16:39,434 - catalog.api.controllers.elasticsearch.search.perform_search - 222][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing query
[2022-07-07 14:16:39,457 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.022s]
[2022-07-07 14:16:39,458 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=0
[2022-07-07 14:16:39,459 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,459 - catalog.api.controllers.elasticsearch.utils.post_process_results - 201][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing additional backfill query depth=0
[07/Jul/2022 14:16:39] "GET /static/rest_framework/css/default.css HTTP/1.1" 200 1152
[07/Jul/2022 14:16:39] "GET /static/rest_framework/css/prettify.css HTTP/1.1" 200 817
[07/Jul/2022 14:16:39] "GET /static/rest_framework/css/bootstrap-tweaks.css HTTP/1.1" 200 3385
[07/Jul/2022 14:16:39] "GET /static/rest_framework/css/bootstrap.min.css HTTP/1.1" 200 121457
[2022-07-07 14:16:39,502 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.042s]
[2022-07-07 14:16:39,502 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=1
[2022-07-07 14:16:39,503 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,503 - catalog.api.controllers.elasticsearch.utils.post_process_results - 201][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing additional backfill query depth=1
[07/Jul/2022 14:16:39] "GET /static/rest_framework/img/grid.png HTTP/1.1" 200 1458
[2022-07-07 14:16:39,531 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.028s]
[2022-07-07 14:16:39,532 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=2
[2022-07-07 14:16:39,532 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,532 - catalog.api.controllers.elasticsearch.utils.post_process_results - 201][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing additional backfill query depth=2
[2022-07-07 14:16:39,547 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.015s]
[2022-07-07 14:16:39,548 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=3
[2022-07-07 14:16:39,548 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,548 - catalog.api.controllers.elasticsearch.utils.post_process_results - 201][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing additional backfill query depth=3
[2022-07-07 14:16:39,565 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.016s]
[2022-07-07 14:16:39,565 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=4
[2022-07-07 14:16:39,566 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,566 - catalog.api.controllers.elasticsearch.utils.post_process_results - 201][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing additional backfill query depth=4
[2022-07-07 14:16:39,579 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.013s]
[2022-07-07 14:16:39,580 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=5
[2022-07-07 14:16:39,580 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,581 - catalog.api.controllers.elasticsearch.utils.post_process_results - 201][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing additional backfill query depth=5
[2022-07-07 14:16:39,588 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.007s]
[2022-07-07 14:16:39,589 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=6
[2022-07-07 14:16:39,589 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,589 - catalog.api.controllers.elasticsearch.utils.post_process_results - 201][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing additional backfill query depth=6
[2022-07-07 14:16:39,598 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.008s]
[2022-07-07 14:16:39,598 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=7
[2022-07-07 14:16:39,598 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,598 - catalog.api.controllers.elasticsearch.utils.post_process_results - 201][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing additional backfill query depth=7
[2022-07-07 14:16:39,611 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.013s]
[2022-07-07 14:16:39,611 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=8
[2022-07-07 14:16:39,612 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,612 - catalog.api.controllers.elasticsearch.utils.post_process_results - 201][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing additional backfill query depth=8
[2022-07-07 14:16:39,619 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.007s]
[2022-07-07 14:16:39,619 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=9
[2022-07-07 14:16:39,619 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,619 - catalog.api.controllers.elasticsearch.utils.post_process_results - 201][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing additional backfill query depth=9
[2022-07-07 14:16:39,627 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.008s]
[2022-07-07 14:16:39,627 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=10
[2022-07-07 14:16:39,628 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,628 - catalog.api.controllers.elasticsearch.utils.post_process_results - 201][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing additional backfill query depth=10
[2022-07-07 14:16:39,636 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.008s]
[2022-07-07 14:16:39,636 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=11
[2022-07-07 14:16:39,636 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,636 - catalog.api.controllers.elasticsearch.utils.post_process_results - 201][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing additional backfill query depth=11
[2022-07-07 14:16:39,646 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.009s]
[2022-07-07 14:16:39,646 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=12
[2022-07-07 14:16:39,647 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,647 - catalog.api.controllers.elasticsearch.utils.post_process_results - 201][INFO] [0c877f0718634f78b45f6ed8437eb3bb] executing additional backfill query depth=12
[2022-07-07 14:16:39,654 - elasticsearch - 265][INFO] [0c877f0718634f78b45f6ed8437eb3bb] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.007s]
[2022-07-07 14:16:39,654 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [0c877f0718634f78b45f6ed8437eb3bb] post processing results depth=13
[2022-07-07 14:16:39,654 - catalog.api.utils.validate_images.validate_images - 24][INFO] [0c877f0718634f78b45f6ed8437eb3bb] no image urls to validate
[2022-07-07 14:16:39,669 - log_request_id.middleware - 47][INFO] [0c877f0718634f78b45f6ed8437eb3bb] method=GET path=/v1/images/ status=200
[07/Jul/2022 14:16:39] "GET /v1/images/?page_size=20&source=poo HTTP/1.1" 200 11407
[2022-07-07 14:16:42,753 - catalog.api.controllers.elasticsearch.search.perform_search - 117][INFO] [a1e8459117264c3dae7d47bb24ce896e] searching with query_serializer.data={"source": "flickr", "filter_dead": true, "mature": false, "qa": false, "page": 1, "page_size": 20} index=image (hashed) ip=6653667704586267427
[2022-07-07 14:16:42,756 - catalog.api.controllers.elasticsearch.utils.exclude_filtered_providers - 47][INFO] [a1e8459117264c3dae7d47bb24ce896e] filtered_providers=
[2022-07-07 14:16:42,756 - catalog.api.controllers.elasticsearch.search.perform_search - 176][INFO] [a1e8459117264c3dae7d47bb24ce896e] searching without query term
[2022-07-07 14:16:42,758 - catalog.api.controllers.elasticsearch.utils.get_query_slice - 161][INFO] [a1e8459117264c3dae7d47bb24ce896e] start_slice=0 end_slice=20
[2022-07-07 14:16:42,759 - catalog.api.controllers.elasticsearch.search.perform_search - 222][INFO] [a1e8459117264c3dae7d47bb24ce896e] executing query
[2022-07-07 14:16:42,779 - elasticsearch - 265][INFO] [a1e8459117264c3dae7d47bb24ce896e] POST http://es:9200/image/_search?preference=6653667704586267427 [status:200 request:0.020s]
[2022-07-07 14:16:42,781 - catalog.api.controllers.elasticsearch.utils.post_process_results - 182][INFO] [a1e8459117264c3dae7d47bb24ce896e] post processing results depth=0
[2022-07-07 14:16:42,817 - log_request_id.middleware - 47][INFO] [a1e8459117264c3dae7d47bb24ce896e] method=GET path=/v1/images/ status=200
[07/Jul/2022 14:16:42] "GET /v1/images/?page_size=20&source=flickr HTTP/1.1" 200 76023
[07/Jul/2022 14:16:42] "GET /static/rest_framework/css/bootstrap.min.css HTTP/1.1" 304 0
[07/Jul/2022 14:16:42] "GET /static/rest_framework/css/bootstrap-tweaks.css HTTP/1.1" 304 0
[07/Jul/2022 14:16:42] "GET /static/rest_framework/css/prettify.css HTTP/1.1" 304 0
[07/Jul/2022 14:16:42] "GET /static/rest_framework/js/ajax-form.js HTTP/1.1" 304 0
[07/Jul/2022 14:16:42] "GET /static/rest_framework/js/csrf.js HTTP/1.1" 304 0
[07/Jul/2022 14:16:42] "GET /static/rest_framework/css/default.css HTTP/1.1" 304 0
[07/Jul/2022 14:16:42] "GET /static/rest_framework/js/bootstrap.min.js HTTP/1.1" 304 0
[07/Jul/2022 14:16:42] "GET /static/rest_framework/js/jquery-3.5.1.min.js HTTP/1.1" 304 0
[07/Jul/2022 14:16:42] "GET /static/rest_framework/js/prettify-min.js HTTP/1.1" 304 0
[07/Jul/2022 14:16:42] "GET /static/rest_framework/js/default.js HTTP/1.1" 304 0
[07/Jul/2022 14:16:42] "GET /static/rest_framework/img/grid.png HTTP/1.1" 304 0 |
@zackkrida that's actually incomplete. If you change the log level to |
@sarayourfriend ah yep, I set the log level on the ES service instead of the web service. Re-testing now! I think it's right now:
|
@zackkrida Can you confirm you checked out this branch and that the containers are running the updated code? The log you shared does not look right. It doesn't exist after my changes and also uses the root logger, which none of the Django API logs should use anymore. |
Thanks! |
This reverts commit ce33572.
This reverts commit ce33572.
* Revert "Fix related media endpoint (#808)" This reverts commit d7962f1. * Selectively revert "Add logging and fix all logging contexts (#790)" This reverts commit ce33572. * Revert "Refactor search controller for consistency and clarity (#778)" Preserves #730 This reverts commit d26df92. * Fix divergent Elasticsearch configurations In #712 Elasticsearch configuration was moved out of the search controller area into the Django settings module. This unifies access to ES from across the application and is part of the refactoring being done to support the ES versioned index, multi-stage deployment. This commit keeps those changes and applies them to the old search_controller.py module that did not exist at the time the configuration change was applied. * Lint * Prevent circular import We can replace the Any back with the serializer type in the future. * Add back related media endpoint integration tests * Lint
Fixes
Fixes #776 by @sarayourfriend
Description
Add logging to the elasticsearch controller methods.
I also went ahead and updated the logging contexts for all our existing logging in the Django app. To learn more about how this works check out the
Logget.getChild
docs for more insight into how this works. These changes are necessary to make it easy to discern the context of the logs without having to repeat some context sigil (like the name of the method) in the log messages. This simplifies the code that adds to the log and also ensures a uniform way of filtering logs by context (i.e., method and module name) across the app.I also added a documentation page describing the approach to logging and the reasoning behind it. Please let me know if any more details should be added here or if the reasons are unclear or otherwise do not make sense.
Testing Instructions
Checkout this branch. Update your local env to have
LOG_LEVEL
set to"DEBUG"
. Run the app locally and then runjust logs web
. Test a few endpoints and confirm that the logging works.Review the added logs and ensure that they are clear and have sufficient context to understand where they're being logged within a method. Remember that the child logger approach ensures that we always know what module and method we're in. We just need to add context (using the code as a map for this context, by the way) enough to be able to tell what's going on from the logs (again, cross referencing with the code). Confirm that I didn't miss any important branches (ideally I've covered all branches except trivial ones).
Checklist
Update index.md
).main
) or a parent feature branch.Developer Certificate of Origin
Developer Certificate of Origin