[MNT] Switch to using logging for all non-user warnings and errors (#77)

* [REF] Refactor tests to use logging

* [MNT] Add logging functionality

* [REF] Switch all non-user warnings to logging

* Add warning levels check

Suggested by Alyssa

* Replace error with warning

app/api/crud.py

@@ -1,7 +1,7 @@
 """CRUD functions called by path operations."""
 
 import asyncio
-import warnings
+import logging
 
 from fastapi import HTTPException
 
@@ -15,8 +15,7 @@ def build_combined_response(
     content = {"errors": node_errors, "responses": cross_node_results}
 
     if node_errors:
-        # TODO: Use logger instead of print. For example of how to set this up for FastAPI, see https://github.com/tiangolo/fastapi/discussions/8517
-        print(
+        logging.warning(
             f"Requests to {len(node_errors)}/{total_nodes} nodes failed: {[node_error['node_name'] for node_error in node_errors]}."
         )
         if len(node_errors) == total_nodes:
@@ -25,7 +24,7 @@ def build_combined_response(
         else:
             content["nodes_response_status"] = "partial success"
     else:
-        print(
+        logging.info(
             f"Requests to all nodes succeeded ({total_nodes}/{total_nodes})."
         )
         content["nodes_response_status"] = "success"
@@ -115,8 +114,7 @@ async def get(
             node_errors.append(
                 {"node_name": node_name, "error": response.detail}
             )
-            # TODO: Replace with logger
-            warnings.warn(
+            logging.warning(
                 f"Request to node {node_name} ({node_url}) did not succeed: {response.detail}"
             )
         else:
@@ -164,8 +162,7 @@ async def get_terms(data_element_URI: str):
             node_errors.append(
                 {"node_name": node_name, "error": response.detail}
             )
-            # TODO: Replace with logger
-            warnings.warn(
+            logging.warning(
                 f"Request to node {node_name} ({node_url}) did not succeed: {response.detail}"
             )
         else:

app/api/utility.py

@@ -1,6 +1,7 @@
 """Constants and utility functions for federation."""
 
 import json
+import logging
 import warnings
 from pathlib import Path
 
@@ -143,12 +144,12 @@ async def create_federation_node_index():
         public_nodes = {}
 
         if local_nodes:
-            warnings.warn(
+            logging.warning(
                 failed_get_warning
                 + f"Federation will be limited to the nodes defined locally for this API: {local_nodes}."
             )
         else:
-            warnings.warn(failed_get_warning)
+            logging.warning(failed_get_warning)
             raise RuntimeError(
                 "No local or public Neurobagel nodes available for federation."
                 "Please define at least one local node in "

app/main.py

@@ -1,5 +1,6 @@
 """Main app."""
 
+import logging
 from contextlib import asynccontextmanager
 
 import uvicorn
@@ -11,6 +12,12 @@
 from .api import utility as util
 from .api.routers import attributes, nodes, query
 
+logger = logging.getLogger("nb-f-API")
+stdout_handler = logging.StreamHandler()
+
+logger.setLevel(logging.INFO)
+logger.addHandler(stdout_handler)
+
 favicon_url = "https://raw.githubusercontent.com/neurobagel/documentation/main/docs/imgs/logo/neurobagel_favicon.png"
 
 

tests/test_attributes.py

@@ -1,12 +1,9 @@
 import httpx
-import pytest
 from fastapi import status
 
 
 def test_partially_failed_terms_fetching_handled_gracefully(
-    test_app,
-    monkeypatch,
-    set_valid_test_federation_nodes,
+    test_app, monkeypatch, set_valid_test_federation_nodes, caplog
 ):
     """
     When some nodes fail while getting term instances for an attribute (/attribute/{data_element_URI}),
@@ -42,11 +39,13 @@ async def mock_httpx_get(self, **kwargs):
 
     monkeypatch.setattr(httpx.AsyncClient, "get", mock_httpx_get)
 
-    with pytest.warns(UserWarning):
-        response = test_app.get("/attributes/nb:Assessment")
+    response = test_app.get("/attributes/nb:Assessment")
 
     assert response.status_code == status.HTTP_207_MULTI_STATUS
 
+    assert len(caplog.records) > 0
+    any(record.levelname == "WARNING" for record in caplog.records)
+
     response_object = response.json()
     assert response_object["errors"] == [
         {
@@ -63,6 +62,7 @@ def test_fully_failed_terms_fetching_handled_gracefully(
     monkeypatch,
     mock_failed_connection_httpx_get,
     set_valid_test_federation_nodes,
+    caplog,
 ):
     """
     When *all* nodes fail while getting term instances for an attribute (/attribute/{data_element_URI}),
@@ -72,10 +72,12 @@ def test_fully_failed_terms_fetching_handled_gracefully(
         httpx.AsyncClient, "get", mock_failed_connection_httpx_get
     )
 
-    with pytest.warns(UserWarning):
-        response = test_app.get("/attributes/nb:Assessment")
+    response = test_app.get("/attributes/nb:Assessment")
 
     assert response.status_code == status.HTTP_207_MULTI_STATUS
+    # We expect several warnings from logging
+    assert len(caplog.records) > 0
+    any(record.levelname == "WARNING" for record in caplog.records)
 
     response = response.json()
     assert response["nodes_response_status"] == "fail"

tests/test_nodes.py

@@ -58,7 +58,9 @@ def mock_httpx_get(**kwargs):
         ]
 
 
-def test_failed_public_nodes_fetching_raises_warning(test_app, monkeypatch):
+def test_failed_public_nodes_fetching_raises_warning(
+    test_app, monkeypatch, caplog
+):
     """Test that when request for remote list of public nodes fails, an informative warning is raised and the federation node index only includes local nodes."""
 
     def mock_parse_nodes_as_dict(path):
@@ -72,25 +74,24 @@ def mock_httpx_get(**kwargs):
     monkeypatch.setattr(util, "parse_nodes_as_dict", mock_parse_nodes_as_dict)
     monkeypatch.setattr(httpx, "get", mock_httpx_get)
 
-    with pytest.warns(UserWarning) as w:
-        with test_app:
-            response = test_app.get("/nodes/")
-            assert util.FEDERATION_NODES == {
-                "https://mylocalnode.org/": "Local Node"
+    with test_app:
+        response = test_app.get("/nodes/")
+        assert util.FEDERATION_NODES == {
+            "https://mylocalnode.org/": "Local Node"
+        }
+        assert response.json() == [
+            {
+                "NodeName": "Local Node",
+                "ApiURL": "https://mylocalnode.org/",
             }
-            assert response.json() == [
-                {
-                    "NodeName": "Local Node",
-                    "ApiURL": "https://mylocalnode.org/",
-                }
-            ]
+        ]
 
-    assert len(w) == 1
+    assert len(caplog.records) == 1
     for warn_substr in [
         "Unable to fetch directory of public Neurobagel nodes",
         "Federation will be limited to the nodes defined locally for this API: {'https://mylocalnode.org/': 'Local Node'}",
     ]:
-        assert warn_substr in w[0].message.args[0]
+        assert warn_substr in caplog.text
 
 
 def test_unset_local_nodes_raises_warning(test_app, monkeypatch):
@@ -139,7 +140,7 @@ def mock_httpx_get(**kwargs):
     assert "No local Neurobagel nodes defined or found" in w[0].message.args[0]
 
 
-def test_no_available_nodes_raises_error(monkeypatch, test_app):
+def test_no_available_nodes_raises_error(monkeypatch, test_app, caplog):
     """Test that when no local or remote nodes are available, an informative error is raised."""
 
     def mock_parse_nodes_as_dict(path):
@@ -159,8 +160,12 @@ def mock_httpx_get(**kwargs):
         with test_app:
             pass
 
-    # Two warnings are expected, one for the failed GET request for public nodes, and one for the lack of local nodes.
-    assert len(w) == 2
+    # Two warnings are expected:
+    # one via logging.warning for the failed GET request for public nodes, and
+    # one via warnings.warn for the lack of local nodes (because User error).
+    assert len(w) == 1
+    assert len(caplog.records) == 1
+    any(record.levelname == "WARNING" for record in caplog.records)
     assert (
         "No local or public Neurobagel nodes available for federation"
         in str(exc_info.value)

tests/test_query.py

@@ -1,4 +1,5 @@
 import json
+import logging
 
 import httpx
 import pytest
@@ -26,9 +27,9 @@ def mocked_single_matching_dataset_result():
 def test_partial_node_failure_responses_handled_gracefully(
     monkeypatch,
     test_app,
-    capsys,
     set_valid_test_federation_nodes,
     mocked_single_matching_dataset_result,
+    caplog,
 ):
     """
     Test that when queries to some nodes return unsuccessful responses, the overall API get request still succeeds,
@@ -49,12 +50,7 @@ async def mock_httpx_get(self, **kwargs):
 
     monkeypatch.setattr(httpx.AsyncClient, "get", mock_httpx_get)
 
-    with pytest.warns(
-        UserWarning,
-        match=r"Second Public Node \(https://secondpublicnode.org/\) did not succeed",
-    ):
-        response = test_app.get("/query/")
-        captured = capsys.readouterr()
+    response = test_app.get("/query/")
 
     assert response.status_code == status.HTTP_207_MULTI_STATUS
     assert response.json() == {
@@ -73,7 +69,11 @@ async def mock_httpx_get(self, **kwargs):
         "nodes_response_status": "partial success",
     }
     assert (
-        "Requests to 1/2 nodes failed: ['Second Public Node']" in captured.out
+        "Second Public Node (https://secondpublicnode.org/) did not succeed"
+        in caplog.text
+    )
+    assert (
+        "Requests to 1/2 nodes failed: ['Second Public Node']" in caplog.text
     )
 
 
@@ -102,11 +102,11 @@ async def mock_httpx_get(self, **kwargs):
 def test_partial_node_request_failures_handled_gracefully(
     monkeypatch,
     test_app,
-    capsys,
     set_valid_test_federation_nodes,
     mocked_single_matching_dataset_result,
     error_to_raise,
     expected_node_message,
+    caplog,
 ):
     """
     Test that when requests to some nodes fail (so there is no response status code), the overall API get request still succeeds,
@@ -123,12 +123,7 @@ async def mock_httpx_get(self, **kwargs):
 
     monkeypatch.setattr(httpx.AsyncClient, "get", mock_httpx_get)
 
-    with pytest.warns(
-        UserWarning,
-        match=r"Second Public Node \(https://secondpublicnode.org/\) did not succeed",
-    ):
-        response = test_app.get("/query/")
-        captured = capsys.readouterr()
+    response = test_app.get("/query/")
 
     assert response.status_code == status.HTTP_207_MULTI_STATUS
 
@@ -146,7 +141,11 @@ async def mock_httpx_get(self, **kwargs):
     assert node_errors[0]["node_name"] == "Second Public Node"
     assert expected_node_message in node_errors[0]["error"]
     assert (
-        "Requests to 1/2 nodes failed: ['Second Public Node']" in captured.out
+        "Second Public Node (https://secondpublicnode.org/) did not succeed"
+        in caplog.text
+    )
+    assert (
+        "Requests to 1/2 nodes failed: ['Second Public Node']" in caplog.text
     )
 
 
@@ -155,7 +154,7 @@ def test_all_nodes_failure_handled_gracefully(
     test_app,
     mock_failed_connection_httpx_get,
     set_valid_test_federation_nodes,
-    capsys,
+    caplog,
 ):
     """
     Test that when queries sent to all nodes fail, the federation API get request still succeeds,
@@ -165,13 +164,10 @@ def test_all_nodes_failure_handled_gracefully(
         httpx.AsyncClient, "get", mock_failed_connection_httpx_get
     )
 
-    with pytest.warns(
-        UserWarning,
-    ) as w:
-        response = test_app.get("/query/")
-        captured = capsys.readouterr()
+    response = test_app.get("/query/")
 
-    assert len(w) == 2
+    # We expect 3 logs here: one warning for each failed node, and one error for the overall failure
+    assert len(caplog.records) == 3
     assert response.status_code == status.HTTP_207_MULTI_STATUS
 
     response = response.json()
@@ -180,20 +176,23 @@ def test_all_nodes_failure_handled_gracefully(
     assert response["responses"] == []
     assert (
         "Requests to 2/2 nodes failed: ['First Public Node', 'Second Public Node']"
-        in captured.out
+        in caplog.text
     )
 
 
 def test_all_nodes_success_handled_gracefully(
     monkeypatch,
     test_app,
-    capsys,
+    caplog,
     set_valid_test_federation_nodes,
     mocked_single_matching_dataset_result,
 ):
     """
     Test that when queries sent to all nodes succeed, the federation API response includes an overall success status and no errors.
     """
+    # Need to set the logging level to INFO so that the success message is captured
+    # pytest by default captures WARNING or above: https://docs.pytest.org/en/stable/how-to/logging.html#caplog-fixture
+    caplog.set_level(logging.INFO)
 
     async def mock_httpx_get(self, **kwargs):
         return httpx.Response(
@@ -203,12 +202,11 @@ async def mock_httpx_get(self, **kwargs):
     monkeypatch.setattr(httpx.AsyncClient, "get", mock_httpx_get)
 
     response = test_app.get("/query/")
-    captured = capsys.readouterr()
 
     assert response.status_code == status.HTTP_200_OK
 
     response = response.json()
     assert response["nodes_response_status"] == "success"
     assert response["errors"] == []
     assert len(response["responses"]) == 2
-    assert "Requests to all nodes succeeded (2/2)" in captured.out
+    assert "Requests to all nodes succeeded (2/2)" in caplog.text