Handle exceptions from prometheus collectors in discovery node

[joaquincasares]

Description

Our prometheus endpoints are currently seeing this:

{"error":["Something caused the server to crash."],"success":false}

Our logs are showing this:

{"levelno": 40, "level": "ERROR", "msg": "Non Audius-derived exception\nTraceback (most recent call last):\n  File \"/usr/lib/python3.9/site-packages/flask/app.py\", line 1838, in full_dispatch_request\n    rv = self.dispatch_request()\n  File \"/usr/lib/python3.9/site-packages/flask/app.py\", line 1824, in dispatch_request\n    return self.view_functions[rule.endpoint](**req.view_args)\n  File \"/audius-discovery-provider/src/queries/prometheus_metrics_exporter.py\", line 43, in prometheus_metrics_exporter\n    PrometheusMetric.populate_collectors()\n  File \"/audius-discovery-provider/src/utils/prometheus_metric.py\", line 77, in populate_collectors\n    collector()\n  File \"/audius-discovery-provider/src/queries/get_celery_tasks.py\", line 30, in celery_tasks_prometheus_exporter\n    metric.save_time({\"task_name\": task[\"name\"]}, start_time=task[\"time_start\"])\nKeyError: 'name'", "timestamp": "2022-05-05 17:23:27,629"}

Let's wrap our collectors with try/except blocks to minimize future collector issues.

Tests

Check that our prometheus endpoint continues to expose metrics:

• https://discoveryprovider2.staging.audius.co/prometheus_metrics
• https://discoveryprovider2.audius.co/prometheus_metrics

Check that our discovery provider metrics are still being displayed:

• http://grafana.audius.co/d/000000004/discovery-provider

Ensure our staging nodes are being scraped without failures:

• http://grafana.audius.co:9090/targets

How will this change be monitored? Are there sufficient logs?

[SidSethi]

@joaquincasares mind linking to the relevant dashboards in PR description? in place of Monitor Grafana for incoming data.

[joaquincasares]

Now seeing where the issue is with the new log lines:

{"levelno": 40, "level": "ERROR", "msg": "Processing failed for task: {'task_id': '552ef680-2cbb-4c5b-9e1b-e7ecc39a09e9', 'task_name': 'update_metrics', 'started_at': 1651784400.00275}\nTraceback (most recent call last):\n  File \"/audius-discovery-provider/src/queries/get_celery_tasks.py\", line 34, in celery_tasks_prometheus_exporter\n    metric.save_time({\"task_name\": task[\"name\"]}, start_time=task[\"time_start\"])\nKeyError: 'name'", "timestamp": "2022-05-05 21:21:37,133"}
{"levelno": 40, "level": "ERROR", "msg": "Processing failed for task: {'task_id': '85b587a6-d232-4a23-80fc-212c762f45d2', 'task_name': 'monitoring_queue', 'started_at': 1651783267.5805767}\nTraceback (most recent call last):\n  File \"/audius-discovery-provider/src/queries/get_celery_tasks.py\", line 34, in celery_tasks_prometheus_exporter\n    metric.save_time({\"task_name\": task[\"name\"]}, start_time=task[\"time_start\"])\nKeyError: 'name'", "timestamp": "2022-05-05 21:21:37,134"}
{"levelno": 40, "level": "ERROR", "msg": "Processing failed for task: {'task_id': 'cac769ac-b530-4afd-9f38-81612d51b0cf', 'task_name': 'index_eth', 'started_at': 1651784448.7092664}\nTraceback (most recent call last):\n  File \"/audius-discovery-provider/src/queries/get_celery_tasks.py\", line 34, in celery_tasks_prometheus_exporter\n    metric.save_time({\"task_name\": task[\"name\"]}, start_time=task[\"time_start\"])\nKeyError: 'name'", "timestamp": "2022-05-05 21:21:37,134"}
{"levelno": 40, "level": "ERROR", "msg": "Processing failed for task: {'task_id': 'c2061b21-9ba3-4b33-9919-d203bc917ce4', 'task_name': 'vacuum_db', 'started_at': 1651783458.180594}\nTraceback (most recent call last):\n  File \"/audius-discovery-provider/src/queries/get_celery_tasks.py\", line 34, in celery_tasks_prometheus_exporter\n    metric.save_time({\"task_name\": task[\"name\"]}, start_time=task[\"time_start\"])\nKeyError: 'name'", "timestamp": "2022-05-05 21:21:37,134"}
{"levelno": 40, "level": "ERROR", "msg": "Processing failed for task: {'task_id': '3e9432c2-0400-4b30-b6f2-0ba79b978fdc', 'task_name': 'index_solana_plays', 'started_at': 1651784448.7501755}\nTraceback (most recent call last):\n  File \"/audius-discovery-provider/src/queries/get_celery_tasks.py\", line 34, in celery_tasks_prometheus_exporter\n    metric.save_time({\"task_name\": task[\"name\"]}, start_time=task[\"time_start\"])\nKeyError: 'name'", "timestamp": "2022-05-05 21:21:37,134"}
{"levelno": 40, "level": "ERROR", "msg": "Processing failed for task: {'task_id': '654dd11c-e71f-4bc2-b46c-a773b6dab5f1', 'task_name': 'index_trending', 'started_at': 1651784421.4895377}\nTraceback (most recent call last):\n  File \"/audius-discovery-provider/src/queries/get_celery_tasks.py\", line 34, in celery_tasks_prometheus_exporter\n    metric.save_time({\"task_name\": task[\"name\"]}, start_time=task[\"time_start\"])\nKeyError: 'name'", "timestamp": "2022-05-05 21:21:37,134"}
{"levelno": 20, "level": "INFO", "msg": "handle flask request", "timestamp": "2022-05-05 21:21:37,141", "method": "GET", "path": "/prometheus_metrics", "status": 200, "duration": 18, "ip": "207.193.120.71", "host": "discoveryprovider2.staging.audius.co", "params": ""}

[joaquincasares]

New metrics are now being ingested:

# HELP audius_dn_celery_running_tasks Multiprocess metric
# TYPE audius_dn_celery_running_tasks gauge
audius_dn_celery_running_tasks{pid="ser",task_name="update_metrics"} 1828.4609746932983
audius_dn_celery_running_tasks{pid="ser",task_name="monitoring_queue"} 2960.883231639862
audius_dn_celery_running_tasks{pid="ser",task_name="index_eth"} 1779.754591703415
audius_dn_celery_running_tasks{pid="ser",task_name="vacuum_db"} 2770.283311843872
audius_dn_celery_running_tasks{pid="ser",task_name="index_solana_plays"} 1779.713775396347
audius_dn_celery_running_tasks{pid="ser",task_name="index_trending"} 1806.9744653701782

[SidSethi]

looks good to me! thanks for linking to stage Discprov and testing there. nice to see the fixes working!

[jonaylor89]

LGTM