search

pacificclimate / pdp

The PCIC Data Portal - Server software to run the entire web application
GNU General Public License v3.0
1 stars 2 forks source link

HTTP 500 Errors in backend for pcds requests with station_observations.PRECIP_TOTAL #256

Open matthewbenstead opened 3 years ago

matthewbenstead commented 3 years ago

I noticed a large number of HTTP 500 errors in the PDP Backend logs: 

2021-10-12 18:47:51 [18] [INFO] 172.18.0.1 - - [12/Oct/2021:18:47:51 +0000] "GET /pcds/lister/raw/ENV-AQN/E206271.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-10%2000%3A00%3A00%22 HTTP/1.1" 500 854 "-" "python-requests/2.23.0"
2021-10-12 18:47:51 [15] [INFO] 172.18.0.1 - - [12/Oct/2021:18:47:51 +0000] "GET /pcds/lister/raw/ENV-AQN/E206271.rsql.ascii?station_observations.time,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-10%2000%3A00%3A00%22 HTTP/1.1" 500 857 "-" "python-requests/2.23.0"
2021-10-12 18:47:52 [28] [INFO] 172.18.0.1 - - [12/Oct/2021:18:47:52 +0000] "GET /pcds/lister/raw/ENV-AQN/E248774.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-10%2000%3A00%3A00%22 HTTP/1.1" 500 857 "-" "python-requests/2.23.0"
2021-10-12 18:47:54 [12] [INFO] 172.18.0.1 - - [12/Oct/2021:18:47:54 +0000] "GET /pcds/lister/raw/ENV-AQN/E292249.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-10%2000%3A00%3A00%22 HTTP/1.1" 500 857 "-" "python-requests/2.23.0"
2021-10-12 18:47:56 [25] [INFO] 172.18.0.1 - - [12/Oct/2021:18:47:56 +0000] "GET /pcds/lister/raw/ENV-AQN/E240337.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-10%2000%3A00%3A00%22 HTTP/1.1" 500 857 "-" "python-requests/2.23.0"
2021-10-12 18:47:57 [25] [INFO] 172.18.0.1 - - [12/Oct/2021:18:47:57 +0000] "GET /pcds/lister/raw/ENV-AQN/E304453.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-10%2000%3A00%3A00%22 HTTP/1.1" 500 857 "-" "python-requests/2.23.0"
2021-10-12 18:47:59 [25] [INFO] 172.18.0.1 - - [12/Oct/2021:18:47:59 +0000] "GET /pcds/lister/raw/ENV-AQN/M116003.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-10%2000%3A00%3A00%22 HTTP/1.1" 500 857 "-" "python-requests/2.23.0"
2021-10-12 18:48:02 [13] [INFO] 172.18.0.1 - - [12/Oct/2021:18:48:02 +0000] "GET /pcds/lister/raw/ENV-AQN/E238705.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-10%2000%3A00%3A00%22 HTTP/1.1" 500 857 "-" "python-requests/2.23.0"
2021-10-12 18:48:05 [25] [INFO] 172.18.0.1 - - [12/Oct/2021:18:48:05 +0000] "GET /pcds/lister/raw/ENV-AQN/M106008.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-10%2000%3A00%3A00%22 HTTP/1.1" 500 857 "-" "python-requests/2.23.0"
2021-10-12 18:50:41 [20] [INFO] 172.18.0.1 - - [12/Oct/2021:18:50:41 +0000] "GET /pcds/lister/raw/FLNRO-WMB/474.rsql.ascii?station_observations.time,station_observations.temperature,station_observations.precipitation&station_observations.time%3E%222021-10-10%2000%3A00%3A00%22 HTTP/1.1" 500 856 "-" "python-requests/2.23.0"

I confirmed this was still occurring by running these requests manually: 

mbenstead@pcic-3001:~$ wget -IHEAD --no-cache "https://data.pacificclimate.org/data/pcds/lister/raw/FLNRO-WMB/474.rsql.ascii?station_observations.time,station_observations.temperature,station_observations.precipitation&station_observations.time%3E%222021-10-11%2000%3A00%3A00%22"
--2021-10-13 08:48:53--  https://data.pacificclimate.org/data/pcds/lister/raw/FLNRO-WMB/474.rsql.ascii?station_observations.time,station_observations.temperature,station_observations.precipitation&station_observations.time%3E%222021-10-11%2000%3A00%3A00%22
Resolving data.pacificclimate.org (data.pacificclimate.org)... 206.12.89.147
Connecting to data.pacificclimate.org (data.pacificclimate.org)|206.12.89.147|:443... connected.
HTTP request sent, awaiting response... 500 Internal Error
2021-10-13 08:48:54 ERROR 500: Internal Error.

mbenstead@pcic-3001:~$ wget -IHEAD --no-cache "https://data.pacificclimate.org/data/pcds/lister/raw/ENV-AQN/M116003.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-11%2000%3A00%3A00%22"
--2021-10-13 14:28:08--  https://data.pacificclimate.org/data/pcds/lister/raw/ENV-AQN/M116003.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-11%2000%3A00%3A00%22
Resolving data.pacificclimate.org (data.pacificclimate.org)... 206.12.89.147
Connecting to data.pacificclimate.org (data.pacificclimate.org)|206.12.89.147|:443... connected.
HTTP request sent, awaiting response... 500 Internal Error
2021-10-13 14:28:10 ERROR 500: Internal Error.

mbenstead@pcic-3001:~$ wget -IHEAD --no-cache "https://data.pacificclimate.org/data/pcds/lister/raw/ENV-AQN/E295892.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-11%2000%3A00%3A00%22"
--2021-10-13 14:28:46--  https://data.pacificclimate.org/data/pcds/lister/raw/ENV-AQN/E295892.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-11%2000%3A00%3A00%22
Resolving data.pacificclimate.org (data.pacificclimate.org)... 206.12.89.147
Connecting to data.pacificclimate.org (data.pacificclimate.org)|206.12.89.147|:443... connected.
HTTP request sent, awaiting response... 500 Internal Error
2021-10-13 14:28:46 ERROR 500: Internal Error.

mbenstead@pcic-3001:~$ wget -IHEAD --no-cache "https://data.pacificclimate.org/data/pcds/lister/raw/ENV-AQN/E223615.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-11%2000%3A00%3A00%22"
--2021-10-13 14:29:20--  https://data.pacificclimate.org/data/pcds/lister/raw/ENV-AQN/E223615.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-11%2000%3A00%3A00%22
Resolving data.pacificclimate.org (data.pacificclimate.org)... 206.12.89.147
Connecting to data.pacificclimate.org (data.pacificclimate.org)|206.12.89.147|:443... connected.
HTTP request sent, awaiting response... 500 Internal Error
2021-10-13 14:29:21 ERROR 500: Internal Error.

On closure inspection though I noticed that only the requests that included station_observations.PRECIP_TOTAL were failing, and that taking one of these request and removing that portion meant it passed: 

mbenstead@pcic-3001:~$ wget -IHEAD --no-cache "https://data.pacificclimate.org/data/pcds/lister/raw/ENV-AQN/E223615.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-11%2000%3A00%3A00%22"
--2021-10-13 14:36:01--  https://data.pacificclimate.org/data/pcds/lister/raw/ENV-AQN/E223615.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN,station_observations.PRECIP_TOTAL&station_observations.time%3E%222021-10-11%2000%3A00%3A00%22
Resolving data.pacificclimate.org (data.pacificclimate.org)... 206.12.89.147
Connecting to data.pacificclimate.org (data.pacificclimate.org)|206.12.89.147|:443... connected.
HTTP request sent, awaiting response... 500 Internal Error
2021-10-13 14:36:02 ERROR 500: Internal Error.

mbenstead@pcic-3001:~$ wget -IHEAD --no-cache "https://data.pacificclimate.org/data/pcds/lister/raw/ENV-AQN/E223615.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN&station_observations.time%3E%222021-10-11%2000%3A00%3A00%22"
--2021-10-13 14:36:09--  https://data.pacificclimate.org/data/pcds/lister/raw/ENV-AQN/E223615.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN&station_observations.time%3E%222021-10-11%2000%3A00%3A00%22
Resolving data.pacificclimate.org (data.pacificclimate.org)... 206.12.89.147
Connecting to data.pacificclimate.org (data.pacificclimate.org)|206.12.89.147|:443... connected.
HTTP request sent, awaiting response... 200 OK
Length: unspecified [text/plain]
Saving to: ‘E223615.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN&station_observations.time>"2021-10-11 00:00:00"’

E223615.rsql.ascii?station_observations.time,station     [ <=>                                                                                                                  ]      37  --.-KB/s    in 0s

2021-10-13 14:36:10 (1.34 MB/s) - ‘E223615.rsql.ascii?station_observations.time,station_observations.TEMP_MEAN&station_observations.time>"2021-10-11 00:00:00"’ saved [37]

Unfortunately there were no errors or stack traces in the container log.

jameshiebert commented 3 years ago

The station in question does not have variable PRECIP_TOTAL. So this request is definitely an error condition. But I'd argue that we should catch the fact that the client is requesting non-existent variables and return an HTTP 400 error.