From 0aafb347a68160b2abfcbe7e4985ced73adfd292 Mon Sep 17 00:00:00 2001 From: rileykk Date: Thu, 6 Oct 2022 13:41:53 -0700 Subject: [PATCH 01/10] Added time & status to insitu request logging --- analysis/webservice/algorithms/doms/insitu.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/analysis/webservice/algorithms/doms/insitu.py b/analysis/webservice/algorithms/doms/insitu.py index 6368a037..4ff408ae 100644 --- a/analysis/webservice/algorithms/doms/insitu.py +++ b/analysis/webservice/algorithms/doms/insitu.py @@ -58,12 +58,15 @@ def query_insitu(dataset, variable, start_time, end_time, bbox, platform, depth_ # Page through all insitu results next_page_url = insitu_endpoints.getEndpoint(provider) while next_page_url is not None and next_page_url != 'NA': + thetime = datetime.now() + logging.info("Starting insitu request") + if session is not None: response = session.get(next_page_url, params=params) else: response = requests.get(next_page_url, params=params) - logging.info(f'Insitu request {response.url}') + logging.info(f'Insitu request {response.url} finished. Code: {response.status_code} Time: {str(datetime.now() - thetime)}') response.raise_for_status() insitu_page_response = response.json() From 5accf131cebd6701114b566de082b416653db147 Mon Sep 17 00:00:00 2001 From: Riley Kuttruff <72955101+RKuttruff@users.noreply.github.com> Date: Thu, 13 Oct 2022 21:32:03 -0700 Subject: [PATCH 02/10] Attempt at logging IS query URL before request is made I suspect there may be an issue with this though... --- analysis/webservice/algorithms/doms/insitu.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/analysis/webservice/algorithms/doms/insitu.py b/analysis/webservice/algorithms/doms/insitu.py index da857d904..3964affe 100644 --- a/analysis/webservice/algorithms/doms/insitu.py +++ b/analysis/webservice/algorithms/doms/insitu.py @@ -5,6 +5,7 @@ import requests from datetime import datetime from webservice.algorithms.doms import config as insitu_endpoints +from urllib.parse import urlencode def query_insitu_schema(): @@ -60,7 +61,7 @@ def query_insitu(dataset, variable, start_time, end_time, bbox, platform, depth_ next_page_url = insitu_endpoints.getEndpoint(provider) while next_page_url is not None and next_page_url != 'NA': thetime = datetime.now() - logging.info("Starting insitu request") + logging.info(f"Starting insitu request: {next_page_url}?{urlencode(params)}") if session is not None: response = session.get(next_page_url, params=params) From 1071995e9b89e6e8c36619fb64c08f097e9b9777 Mon Sep 17 00:00:00 2001 From: rileykk Date: Fri, 14 Oct 2022 12:16:21 -0700 Subject: [PATCH 03/10] Handle logging for next page --- analysis/webservice/algorithms/doms/insitu.py | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/analysis/webservice/algorithms/doms/insitu.py b/analysis/webservice/algorithms/doms/insitu.py index 3964affe..1c451b32 100644 --- a/analysis/webservice/algorithms/doms/insitu.py +++ b/analysis/webservice/algorithms/doms/insitu.py @@ -61,7 +61,10 @@ def query_insitu(dataset, variable, start_time, end_time, bbox, platform, depth_ next_page_url = insitu_endpoints.getEndpoint(provider) while next_page_url is not None and next_page_url != 'NA': thetime = datetime.now() - logging.info(f"Starting insitu request: {next_page_url}?{urlencode(params)}") + if params == {}: + logging.info(f"Starting insitu request: {next_page_url}") + else: + logging.info(f"Starting insitu request: {next_page_url}?{urlencode(params)}") if session is not None: response = session.get(next_page_url, params=params) From b3de5618f155b378ab4b14ccd6000952e78ea2c1 Mon Sep 17 00:00:00 2001 From: rileykk Date: Fri, 14 Oct 2022 12:47:20 -0700 Subject: [PATCH 04/10] Changelog --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 7f7462f6..dd1e9fc8 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -27,6 +27,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - Matchup returns numSecondary and numPrimary counts rather than insitu/gridded - SDAP-402: Changed matchup matchOnce logic to match multiple points if same time/space - Bumped ingress timeout in Helm chart to reflect AWS gateway timeout +- Added logging message for start of insitu query + added status code & elapsed time to post query log message. ### Deprecated ### Removed - removed dropdown from matchup doms endpoint secondary param From 5e35ca655eb2739ec9c7fb0d0ba08ae62ad03735 Mon Sep 17 00:00:00 2001 From: rileykk Date: Mon, 24 Oct 2022 13:00:40 -0700 Subject: [PATCH 05/10] Added explicit timeouts plus NPEs on timout --- analysis/webservice/algorithms/doms/insitu.py | 19 ++++++++++++++----- 1 file changed, 14 insertions(+), 5 deletions(-) diff --git a/analysis/webservice/algorithms/doms/insitu.py b/analysis/webservice/algorithms/doms/insitu.py index c82802e3..116afba0 100644 --- a/analysis/webservice/algorithms/doms/insitu.py +++ b/analysis/webservice/algorithms/doms/insitu.py @@ -6,6 +6,7 @@ from datetime import datetime from webservice.algorithms.doms import config as insitu_endpoints from urllib.parse import urlencode +from webservice.webmodel import NexusProcessingException def query_insitu_schema(): @@ -16,7 +17,11 @@ def query_insitu_schema(): """ schema_endpoint = insitu_endpoints.getSchemaEndpoint() logging.info("Querying schema") - response = requests.get(schema_endpoint) + try: + response = requests.get(schema_endpoint) + except (requests.exceptions.ReadTimeout, requests.exceptions.ConnectTimeout): + raise NexusProcessingException(code=504, reason=f'Insitu schema request timed out') + response.raise_for_status() return response.json() @@ -67,10 +72,14 @@ def query_insitu(dataset, variable, start_time, end_time, bbox, platform, depth_ else: logging.info(f"Starting insitu request: {next_page_url}?{urlencode(params)}") - if session is not None: - response = session.get(next_page_url, params=params) - else: - response = requests.get(next_page_url, params=params) + + try: + if session is not None: + response = session.get(next_page_url, params=params, timeout=(15.05, 331)) + else: + response = requests.get(next_page_url, params=params, timeout=(15.05, 331)) + except (requests.exceptions.ReadTimeout, requests.exceptions.ConnectTimeout): + raise NexusProcessingException(code=504, reason=f'Insitu request timed out after {str(datetime.now() - thetime)} seconds') logging.info(f'Insitu request {response.url} finished. Code: {response.status_code} Time: {str(datetime.now() - thetime)}') From 88418613474040254dee28e018d7ff4e3e7e82e0 Mon Sep 17 00:00:00 2001 From: rileykk Date: Mon, 24 Oct 2022 13:03:30 -0700 Subject: [PATCH 06/10] Updated CHANGELOG.md --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index cde180ae..09f0313b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -31,6 +31,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - SDAP-399: Updated quickstart guide for standalone docker deployment of SDAP. - SDAP-399: Updated quickstart Jupyter notebook - Added logging message for start of insitu query + added status code & elapsed time to post query log message. +- Added explicit timeouts for all insitu related queries to prevent hanging issue. ### Deprecated ### Removed - removed dropdown from matchup doms endpoint secondary param From c595569e5385dddfee3b781bfcdfd3ae3453228e Mon Sep 17 00:00:00 2001 From: rileykk Date: Mon, 24 Oct 2022 13:05:01 -0700 Subject: [PATCH 07/10] Schema timeout --- analysis/webservice/algorithms/doms/insitu.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/analysis/webservice/algorithms/doms/insitu.py b/analysis/webservice/algorithms/doms/insitu.py index 116afba0..b9165c88 100644 --- a/analysis/webservice/algorithms/doms/insitu.py +++ b/analysis/webservice/algorithms/doms/insitu.py @@ -18,7 +18,7 @@ def query_insitu_schema(): schema_endpoint = insitu_endpoints.getSchemaEndpoint() logging.info("Querying schema") try: - response = requests.get(schema_endpoint) + response = requests.get(schema_endpoint, timeout=(15.05, 331)) except (requests.exceptions.ReadTimeout, requests.exceptions.ConnectTimeout): raise NexusProcessingException(code=504, reason=f'Insitu schema request timed out') From ececbd0f60babd0bfde4a95428368d43d2242be5 Mon Sep 17 00:00:00 2001 From: rileykk Date: Tue, 25 Oct 2022 15:03:02 -0700 Subject: [PATCH 08/10] Made timeout variables --- analysis/webservice/algorithms/doms/insitu.py | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/analysis/webservice/algorithms/doms/insitu.py b/analysis/webservice/algorithms/doms/insitu.py index b9165c88..53ec8b05 100644 --- a/analysis/webservice/algorithms/doms/insitu.py +++ b/analysis/webservice/algorithms/doms/insitu.py @@ -9,6 +9,11 @@ from webservice.webmodel import NexusProcessingException +CONNECT_TIMEOUT = 9.05 # Recommended to be just above a multiple of 3 seconds +READ_TIMEOUT = 303 # Just above current gateway timeout +TIMEOUTS = (CONNECT_TIMEOUT, READ_TIMEOUT) + + def query_insitu_schema(): """ Query the "cdms_schema" insitu endpoint. This will return the JSON @@ -18,7 +23,7 @@ def query_insitu_schema(): schema_endpoint = insitu_endpoints.getSchemaEndpoint() logging.info("Querying schema") try: - response = requests.get(schema_endpoint, timeout=(15.05, 331)) + response = requests.get(schema_endpoint, timeout=TIMEOUTS) except (requests.exceptions.ReadTimeout, requests.exceptions.ConnectTimeout): raise NexusProcessingException(code=504, reason=f'Insitu schema request timed out') @@ -75,9 +80,9 @@ def query_insitu(dataset, variable, start_time, end_time, bbox, platform, depth_ try: if session is not None: - response = session.get(next_page_url, params=params, timeout=(15.05, 331)) + response = session.get(next_page_url, params=params, timeout=TIMEOUTS) else: - response = requests.get(next_page_url, params=params, timeout=(15.05, 331)) + response = requests.get(next_page_url, params=params, timeout=TIMEOUTS) except (requests.exceptions.ReadTimeout, requests.exceptions.ConnectTimeout): raise NexusProcessingException(code=504, reason=f'Insitu request timed out after {str(datetime.now() - thetime)} seconds') From 469d7894e254dd879db9e4e14269044ead7b58f7 Mon Sep 17 00:00:00 2001 From: rileykk Date: Wed, 14 Dec 2022 12:14:53 -0800 Subject: [PATCH 09/10] Moved changelog entry --- CHANGELOG.md | 12 ++++++++++-- 1 file changed, 10 insertions(+), 2 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 2e761b1e..ab0b9131 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -4,6 +4,16 @@ All notable changes to this project will be documented in this file. The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/), and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html). +## [Unreleased] +### Added +- Added logging message for start of insitu query + added status code & elapsed time to post query log message. +- Added explicit timeouts for all insitu related queries to prevent hanging issue. +### Changed +### Deprecated +### Removed +### Fixed +### Security + ## [1.0.0] - 2022-11-22 ### Added - SDAP-388: Enable SDAP to proxy/redirect to alternate SDAP @@ -35,8 +45,6 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0 - SDAP-399: Updated quickstart Jupyter notebook - SDAP-411: Used global versioning for SDAP NEXUS artifacts - SDAP-416: Using mamba to install nexus-analysis dependencies. (Also using conda as a fallback option if mamba install fails) -- Added logging message for start of insitu query + added status code & elapsed time to post query log message. -- Added explicit timeouts for all insitu related queries to prevent hanging issue. ### Deprecated ### Removed - removed dropdown from matchup doms endpoint secondary param From 90e086dfb5510ff93484361e51d095ddfffbd60b Mon Sep 17 00:00:00 2001 From: rileykk Date: Thu, 2 Mar 2023 13:18:10 -0800 Subject: [PATCH 10/10] Logging: non-root + log count of returned points --- analysis/webservice/algorithms/doms/insitu.py | 12 ++++++++---- 1 file changed, 8 insertions(+), 4 deletions(-) diff --git a/analysis/webservice/algorithms/doms/insitu.py b/analysis/webservice/algorithms/doms/insitu.py index ae082391..07b741ac 100644 --- a/analysis/webservice/algorithms/doms/insitu.py +++ b/analysis/webservice/algorithms/doms/insitu.py @@ -28,6 +28,8 @@ READ_TIMEOUT = 303 # Just above current gateway timeout TIMEOUTS = (CONNECT_TIMEOUT, READ_TIMEOUT) +logger = logging.getLogger(__name__) + def query_insitu_schema(): """ @@ -36,7 +38,7 @@ def query_insitu_schema(): metadata """ schema_endpoint = insitu_endpoints.getSchemaEndpoint() - logging.info("Querying schema") + logger.info("Querying schema") try: response = requests.get(schema_endpoint, timeout=TIMEOUTS) except (requests.exceptions.ReadTimeout, requests.exceptions.ConnectTimeout): @@ -88,9 +90,9 @@ def query_insitu(dataset, variable, start_time, end_time, bbox, platform, depth_ while next_page_url is not None and next_page_url != 'NA': thetime = datetime.now() if params == {}: - logging.info(f"Starting insitu request: {next_page_url}") + logger.info(f"Starting insitu request: {next_page_url}") else: - logging.info(f"Starting insitu request: {next_page_url}?{urlencode(params)}") + logger.info(f"Starting insitu request: {next_page_url}?{urlencode(params)}") try: @@ -101,7 +103,7 @@ def query_insitu(dataset, variable, start_time, end_time, bbox, platform, depth_ except (requests.exceptions.ReadTimeout, requests.exceptions.ConnectTimeout): raise NexusProcessingException(code=504, reason=f'Insitu request timed out after {str(datetime.now() - thetime)} seconds') - logging.info(f'Insitu request {response.url} finished. Code: {response.status_code} Time: {str(datetime.now() - thetime)}') + logger.info(f'Insitu request {response.url} finished. Code: {response.status_code} Time: {str(datetime.now() - thetime)}') response.raise_for_status() insitu_page_response = response.json() @@ -114,4 +116,6 @@ def query_insitu(dataset, variable, start_time, end_time, bbox, platform, depth_ next_page_url = insitu_page_response.get('next', None) params = {} # Remove params, they are already included in above URL + logger.info(f"Insitu query completed, returning {len(insitu_response['results']):,} points") + return insitu_response