Issue #146 - Improve/correlation logging (!140) · Merge requests · OSDU Software / OSDU Data Platform / Domain Data Management Services / Rock and Fluid Sample / rafs-ddms-services

Arturo Hernandez [EPAM] requested to merge improve/correlation_log_generic into main Oct 26, 2023

Type of change

Bug Fix
Feature

Does this introduce a change in the core logic?

[Yes] - It introduces better logging configuration to be more readable and integrated with the correlation id for better traceability (like other java-based services does)

Does this introduce a change in the cloud provider implementation, and if so which cloud?

AWS
Azure
GCP
IBM

Does this introduce a change that must be documented in the README.md file?

[No] Improvement of the log

Updates description?

Loggers initialization refactor to use logging filter.
Slight changes on the middleware to modify correlation-id on core requests and to generate correlation id and registered in the context var.
https://github.com/tiangolo/fastapi/issues/397
https://fastapi.tiangolo.com/tutorial/middleware/

Previous log output

rafs-ddms-648b69dbc7-9vk72 rafs-ddms 2023-10-26 16:03:29.556 | ERROR    | app.services.error_handlers:wrapper:43 - {"code":404,"reason":"Version not found","message":"The version 1698336208 can't be found for record opendes:work-product-component--MultipleContactMiscibilityTest:autotest_ppPIa7RHZY"}
rafs-ddms-648b69dbc7-9vk72 rafs-ddms 2023-10-26 16:03:29.558 | INFO     | logging:handle:978 - 127.0.0.6:42109 - "GET /api/rafs-ddms/v1/multiplecontactmiscibilitytests/opendes%3Awork-product-component--MultipleContactMiscibilityTest%3Aautotest_ppPIa7RHZY/versions/1698336208 HTTP/1.1" 404
rafs-ddms-648b69dbc7-9vk72 rafs-ddms 2023-10-26 16:03:29.765 | INFO     | logging:handle:978 - 127.0.0.6:48963 - "GET /api/rafs-ddms/v2/samplesanalysis/opendes%3Awork-product-component--SamplesAnalysis%3Aautotest_XaYhTdn0D5 HTTP/1.1" 200
rafs-ddms-648b69dbc7-9vk72 rafs-ddms 2023-10-26 16:03:29.869 | INFO     | logging:handle:978 - 127.0.0.6:42109 - "GET /api/rafs-ddms/v1/constantvolumedepletiontests/opendes%3Awork-product-component--ConstantVolumeDepletionTest%3Aautotest_zwYaali3dF HTTP/1.1" 200
rafs-ddms-648b69dbc7-9vk72 rafs-ddms 2023-10-26 16:03:29.890 | INFO     | app.api.routes.data.api:_upsert_dataset:414 - File uploaded for new dataset: opendes:dataset--File.Generic:routine-core-analysis-06a70301-4552-415e-81ea-c05a9e3c7a04
rafs-ddms-648b69dbc7-9vk72 rafs-ddms 2023-10-26 16:03:30.118 | INFO     | logging:handle:978 - 127.0.0.6:43601 - "GET /api/rafs-ddms/v1/physicalchemistrytests/opendes%3Awork-product-component--SamplesAnalysis%3Aautotest_7MF7DNRYri/data/opendes%3Adataset--File.Generic%3Aphysical-chemistryautotest_0BQlWkrjbA HTTP/1.1" 400
rafs-ddms-648b69dbc7-9vk72 rafs-ddms 2023-10-26 16:03:30.152 | INFO     | app.api.routes.data.api:_upsert_dataset:418 - Updated record: {'recordCount': 1, 'recordIds': ['opendes:work-product-component--RockSampleAnalysis:autotest_daWwO0y3zp'], 'skippedRecordIds': [], 'recordIdVersions': ['opendes:work-product-component--RockSampleAnalysis:autotest_daWwO0y3zp:1698336210002516']}
rafs-ddms-648b69dbc7-9vk72 rafs-ddms 2023-10-26 16:03:30.153 | INFO     | logging:handle:978 - 127.0.0.6:54607 - "POST /api/rafs-ddms/v1/rocksampleanalyses/opendes%3Awork-product-component--RockSampleAnalysis%3Aautotest_daWwO0y3zp/rca/data HTTP/1.1" 200

Log output suggested by this MR (correlation id):

Attaching to rafs-ddms-services_rafs_1
rafs_1         | INFO:     Will watch for changes in these directories: ['/app']
rafs_1         | WARNING:  "workers" flag is ignored when reloading is enabled.
rafs_1         | INFO:     Uvicorn running on http://0.0.0.0:8080 (Press CTRL+C to quit)
rafs_1         | INFO:     Started reloader process [1] using WatchFiles
rafs_1         | 2023-10-26 18:55:46,256 [8][INFO] --- {correlation-id=None} uvicorn.error: Started server process [8]
rafs_1         | 2023-10-26 18:55:46,257 [8][INFO] --- {correlation-id=None} uvicorn.error: Waiting for application startup.
rafs_1         | 2023-10-26 18:55:46,257 [8][DEBUG] --- {correlation-id=None} app.core.events: App started with settings: app_env=<AppEnvTypes.prod: 'prod'> commit_id='' commit_message='Local Development' commit_branch='Local' build_date='' cloud_provider='azure' schema_authority='osdu' custom_schema_authority='rafsddms' request_timeout=180.0 release_version='0.0.0-local' debug=False app_name='Rock and Fluid Sample DDMS' app_version='0.2.0' ddms_id='rafs' openapi_prefix='/api/rafs-ddms' allowed_hosts=['*'] logging_level=10 loggers=('uvicorn.asgi', 'uvicorn.access', 'uvicorn.error') service_host_search='https://osdu-glab.msft-osdu-test.org/api/search/v2' service_host_storage='https://osdu-glab.msft-osdu-test.org/api/storage/v2' service_host_partition='https://osdu-glab.msft-osdu-test.org/api/partition/v1' service_host_dataset='https://osdu-glab.msft-osdu-test.org/api/dataset/v1' user_token=None cache_enable=False cache_backend='' storage_query_limit=100
rafs_1         | 2023-10-26 18:55:46,257 [8][DEBUG] --- {correlation-id=None} app.core.helpers.cache_helper: Fastapi cache disabled
rafs_1         | 2023-10-26 18:55:46,257 [8][DEBUG] --- {correlation-id=None} app.core.helpers.cache_helper: Fastapi cache initialized with settings: backend=, prefix=/api/rafs-ddms, enable=False
rafs_1         | 2023-10-26 18:55:46,257 [8][INFO] --- {correlation-id=None} uvicorn.error: Application startup complete.
rafs_1         | 2023-10-26 18:56:07,164 [8][DEBUG] --- {correlation-id=rafs-ddms/autotest/049eb597-ed6e-4451-9439-90e549216dbf} app.api.dependencies.validation: Records successfully validated for rafsddms:wks:work-product-component--PVT:1.0.0
rafs_1         | 2023-10-26 18:56:09,004 [8][DEBUG] --- {correlation-id=rafs-ddms/autotest/049eb597-ed6e-4451-9439-90e549216dbf} app.services.osdu_clients.storage_client: StorageService: upsert records response: <Response [201 Created]>
rafs_1         | 2023-10-26 18:56:09,006 [8][INFO] --- {correlation-id=rafs-ddms/autotest/049eb597-ed6e-4451-9439-90e549216dbf} uvicorn.access: 172.18.0.4:60912 - "POST /api/rafs-ddms/v1/pvtreports HTTP/1.1" 200
rafs_1         | 2023-10-26 18:56:09,038 [8][DEBUG] --- {correlation-id=None} app.api.dependencies.validation: Records successfully validated for rafsddms:wks:work-product-component--SamplesAnalysesReport:1.0.0
rafs_1         | 2023-10-26 18:56:10,318 [8][DEBUG] --- {correlation-id=rafs-ddms/autotest/26ef5eba-49eb-4a2b-a57d-242ce9a3b9a3} app.services.osdu_clients.storage_client: StorageService: upsert records response: <Response [201 Created]>
rafs_1         | 2023-10-26 18:56:10,320 [8][INFO] --- {correlation-id=rafs-ddms/autotest/26ef5eba-49eb-4a2b-a57d-242ce9a3b9a3} uvicorn.access: 172.18.0.4:60922 - "POST /api/rafs-ddms/v1/samplesanalysesreport HTTP/1.1" 200
rafs_1         | 2023-10-26 18:56:10,346 [8][DEBUG] --- {correlation-id=None} app.api.dependencies.validation: Records successfully validated for osdu:wks:master-data--RockSample:1.0.0
rafs_1         | 2023-10-26 18:56:11,468 [8][DEBUG] --- {correlation-id=rafs-ddms/autotest/129fdb47-ec6c-4697-89b8-cb5da79f4884} app.services.osdu_clients.storage_client: StorageService: upsert records response: <Response [201 Created]>
rafs_1         | 2023-10-26 18:56:11,470 [8][INFO] --- {correlation-id=rafs-ddms/autotest/129fdb47-ec6c-4697-89b8-cb5da79f4884} uvicorn.access: 172.18.0.4:60930 - "POST /api/rafs-ddms/v1/rocksamples HTTP/1.1" 200
rafs_1         | 2023-10-26 18:56:12,326 [8][DEBUG] --- {correlation-id=rafs-ddms/autotest/7f3e98d3-a741-40f5-be29-1cc4d67d9d95} app.services.osdu_clients.storage_client: StorageService: get latest version of record response: <Response [200 OK]>
rafs_1         | 2023-10-26 18:56:12,329 [8][INFO] --- {correlation-id=rafs-ddms/autotest/7f3e98d3-a741-40f5-be29-1cc4d67d9d95} uvicorn.access: 172.18.0.4:60932 - "GET /api/rafs-ddms/v1/rocksamples/opendes%3Amaster-data--RockSample%3Aautotest_xQFeDMirOC HTTP/1.1" 200
rafs_1         | 2023-10-26 18:56:13,231 [8][DEBUG] --- {correlation-id=rafs-ddms/autotest/67dc545a-6165-4edb-8789-ab53b5f47219} app.services.osdu_clients.storage_client: StorageService: soft delete record response: <Response [204 No Content]>
rafs_1         | 2023-10-26 18:56:13,232 [8][INFO] --- {correlation-id=rafs-ddms/autotest/67dc545a-6165-4edb-8789-ab53b5f47219} uvicorn.access: 172.18.0.4:32840 - "DELETE /api/rafs-ddms/v1/rocksamples/opendes%3Amaster-data--RockSample%3Aautotest_xQFeDMirOC HTTP/1.1" 204
rafs_1         | 2023-10-26 18:56:14,051 [8][DEBUG] --- {correlation-id=rafs-ddms/autotest/dd1ac886-849a-4a19-b945-0cfe115f0637} app.services.osdu_clients.storage_client: StorageService: get latest version of record response: <Response [404 Not Found]>
rafs_1         | 2023-10-26 18:56:14,052 [8][ERROR] --- {correlation-id=rafs-ddms/autotest/dd1ac886-849a-4a19-b945-0cfe115f0637} app.services.error_handlers: {"code":404,"reason":"Record not found","message":"The record with the given ID is not active"}
rafs_1         | 2023-10-26 18:56:14,054 [8][INFO] --- {correlation-id=rafs-ddms/autotest/dd1ac886-849a-4a19-b945-0cfe115f0637} uvicorn.access: 172.18.0.4:32848 - "GET /api/rafs-ddms/v1/rocksamples/opendes%3Amaster-data--RockSample%3Aautotest_xQFeDMirOC HTTP/1.1" 404
rafs_1         | 2023-10-26 18:56:15,932 [8][DEBUG] --- {correlation-id=None} app.api.dependencies.validation: Records successfully validated for osdu:wks:master-data--Coring:1.0.0
rafs_1         | 2023-10-26 18:56:16,882 [8][DEBUG] --- {correlation-id=rafs-ddms/autotest/c79f49ed-2c69-46ae-9160-56b2e00a9675} app.services.osdu_clients.storage_client: StorageService: upsert records response: <Response [201 Created]>
rafs_1         | 2023-10-26 18:56:16,885 [8][INFO] --- {correlation-id=rafs-ddms/autotest/c79f49ed-2c69-46ae-9160-56b2e00a9675} uvicorn.access: 172.18.0.4:32864 - "POST /api/rafs-ddms/v1/coringreports HTTP/1.1" 200
rafs_1         | 2023-10-26 18:56:17,720 [8][DEBUG] --- {correlation-id=rafs-ddms/autotest/f5ab77ea-af23-4c6b-a831-63498250b930} app.services.osdu_clients.storage_client: StorageService: get latest version of record response: <Response [200 OK]>
rafs_1         | 2023-10-26 18:56:17,727 [8][INFO] --- {correlation-id=rafs-ddms/autotest/f5ab77ea-af23-4c6b-a831-63498250b930} uvicorn.access: 172.18.0.4:32872 - "GET /api/rafs-ddms/v1/coringreports/opendes%3Amaster-data--Coring%3Aautotest_MNN4cT8rXz HTTP/1.1" 200
rafs_1         | 2023-10-26 18:56:18,645 [8][DEBUG] --- {correlation-id=rafs-ddms/autotest/20e7397e-b022-44be-a2e7-bd5419f04b7c} app.services.osdu_clients.storage_client: StorageService: soft delete record response: <Response [204 No Content]>

This will allow us to troubleshoot in an efficient way, and will allow us also to correlate tracing logs RAFS->processes->core-services

Issue #146 - Improve/correlation logging

Type of change

Does this introduce a change in the core logic?

Does this introduce a change in the cloud provider implementation, and if so which cloud?

Does this introduce a change that must be documented in the README.md file?

Updates description?

Previous log output

Merge request reports