Merge branch 'main' into andycochran/873--milestone-layout

api/openapi.generated.yml

@@ -337,6 +337,19 @@ components:
           - O
           type:
           - string
+        category_explanation:
+          type: string
+          description: Explanation of the category when the category is 'O' (other)
+          example: null
+        revision_number:
+          type: integer
+          description: The current revision number of the opportunity, counting starts
+            at 0
+          example: 0
+        modified_comments:
+          type: string
+          description: Details regarding what modification was last made
+          example: null
         created_at:
           type: string
           format: date-time

api/src/api/opportunities/opportunity_routes.py

@@ -7,8 +7,10 @@
 from src.api.feature_flags.feature_flag_config import FeatureFlagConfig
 from src.api.opportunities.opportunity_blueprint import opportunity_blueprint
 from src.auth.api_key_auth import api_key_auth
+from src.logging.flask_logger import add_extra_data_to_current_request_logs
 from src.services.opportunities.get_opportunities import get_opportunity
 from src.services.opportunities.search_opportunities import search_opportunities
+from src.util.dict_util import flatten_dict
 
 logger = logging.getLogger(__name__)
 
@@ -27,12 +29,24 @@
 def opportunity_search(
     db_session: db.Session, search_params: dict, feature_flag_config: FeatureFlagConfig
 ) -> response.ApiResponse:
+    # Attach the request parameters to all logs for the rest of the request lifecycle
+    add_extra_data_to_current_request_logs(flatten_dict(search_params, prefix="request.body"))
+    logger.info("POST /v1/opportunities/search")
+
     if feature_flag_config.enable_opportunity_log_msg:
         logger.info("Feature flag enabled")
 
     with db_session.begin():
         opportunities, pagination_info = search_opportunities(db_session, search_params)
 
+    add_extra_data_to_current_request_logs(
+        {
+            "response.pagination.total_pages": pagination_info.total_pages,
+            "response.pagination.total_records": pagination_info.total_records,
+        }
+    )
+    logger.info("Successfully fetched opportunities")
+
     return response.ApiResponse(
         message="Success", data=opportunities, pagination_info=pagination_info
     )
@@ -43,6 +57,8 @@ def opportunity_search(
 @opportunity_blueprint.auth_required(api_key_auth)
 @flask_db.with_db_session()
 def opportunity_get(db_session: db.Session, opportunity_id: int) -> response.ApiResponse:
+    add_extra_data_to_current_request_logs({"request.path.opportunity_id": opportunity_id})
+    logger.info("GET /v1/opportunities/:opportunity_id")
     with db_session.begin():
         opportunity = get_opportunity(db_session, opportunity_id)
 

api/src/api/opportunities/opportunity_schemas.py

@@ -35,6 +35,25 @@ class OpportunitySchema(Schema):
             "example": OpportunityCategory.DISCRETIONARY,
         },
     )
+    category_explanation = fields.String(
+        metadata={
+            "description": "Explanation of the category when the category is 'O' (other)",
+            "example": None,
+        }
+    )
+
+    revision_number = fields.Integer(
+        metadata={
+            "description": "The current revision number of the opportunity, counting starts at 0",
+            "example": 0,
+        }
+    )
+    modified_comments = fields.String(
+        metadata={
+            "description": "Details regarding what modification was last made",
+            "example": None,
+        }
+    )
 
     created_at = fields.DateTime(dump_only=True)
     updated_at = fields.DateTime(dump_only=True)

api/src/auth/api_key_auth.py

@@ -74,7 +74,7 @@ def process_token(token: str) -> User:
     expected_auth_token = os.getenv("API_AUTH_TOKEN", None)
 
     if not expected_auth_token:
-        logger.info(
+        logger.error(
             "Authentication is not setup, please add an API_AUTH_TOKEN environment variable."
         )
         abort(401, "Authentication is not setup properly and the user cannot be authenticated")

api/src/logging/audit.py

@@ -13,7 +13,6 @@
 logger = logging.getLogger(__name__)
 
 AUDIT = 32
-logging.INFO
 logging.addLevelName(AUDIT, "AUDIT")
 
 

api/src/logging/flask_logger.py

@@ -18,6 +18,7 @@
 """
 import logging
 import time
+import uuid
 
 import flask
 
@@ -154,6 +155,9 @@ def _get_request_context_info(request: flask.Request) -> dict:
         "request.method": request.method,
         "request.path": request.path,
         "request.url_rule": str(request.url_rule),
+        # A backup ID in case the x-amzn-requestid isn't passed in
+        # doesn't help with tracing across systems, but at least links within a request
+        "request.internal_id": str(uuid.uuid4()),
     }
 
     # Add query parameter data in the format request.query.<key> = <value>

api/tests/src/db/models/factories.py

@@ -75,7 +75,12 @@ class Meta:
     agency = factory.Iterator(["US-ABC", "US-XYZ", "US-123"])
 
     category = factory.fuzzy.FuzzyChoice(OpportunityCategory)
-    category_explanation = factory.Sequence(lambda n: f"Category as chosen by order #{n * n - 1}")
+    # only set the category explanation if category is Other
+    category_explanation = factory.Maybe(
+        decider=factory.LazyAttribute(lambda o: o.category == OpportunityCategory.OTHER),
+        yes_declaration=factory.Sequence(lambda n: f"Category as chosen by order #{n * n - 1}"),
+        no_declaration=None,
+    )
 
     is_draft = False  # Because we filter out drafts, just default these to False
 

api/tests/src/route/test_opportunity_route.py

@@ -374,8 +374,17 @@ def test_opportunity_search_feature_flag_invalid_value_422(
 #####################################
 
 
-def test_get_opportunity_200(client, api_auth_token, enable_factory_create):
-    opportunity = OpportunityFactory.create()
+@pytest.mark.parametrize(
+    "opportunity_params",
+    [
+        # Whatever defaults we have in the factory
+        {},
+        # Set several values that can be null
+        {"revision_number": 5, "modified_comments": "I changed it"},
+    ],
+)
+def test_get_opportunity_200(client, api_auth_token, enable_factory_create, opportunity_params):
+    opportunity = OpportunityFactory.create(**opportunity_params)
 
     resp = client.get(
         f"/v1/opportunities/{opportunity.opportunity_id}", headers={"X-Auth": api_auth_token}
@@ -388,6 +397,9 @@ def test_get_opportunity_200(client, api_auth_token, enable_factory_create):
     assert response_data["opportunity_title"] == opportunity.opportunity_title
     assert response_data["agency"] == opportunity.agency
     assert response_data["category"] == opportunity.category
+    assert response_data["category_explanation"] == opportunity.category_explanation
+    assert response_data["revision_number"] == opportunity.revision_number
+    assert response_data["modified_comments"] == opportunity.modified_comments
 
 
 def test_get_opportunity_not_found_404(client, api_auth_token, truncate_opportunities):

documentation/api/monitoring-and-observability/logging-configuration.md

@@ -4,6 +4,39 @@
 
 This document describes how logging is configured in the application. The logging functionality is defined in the [src.logging](../../../api/src/logging/) package and leverages Python's built-in [logging](https://docs.python.org/3/library/logging.html) framework.
 
+## Usage
+Our logging approach uses a context manager to start up and tear down logging. This is mostly done to prevent tests from
+setting up multiple loggers each time we instantiate the logger.
+
+If you wanted to write a simple script that could log, something like this would work
+
+```py
+import logging
+
+import src.logging
+
+logger = logging.getLogger(__name__)
+
+def main():
+    with src.logging.init(__package__):
+        logger.info("Hello")
+```
+
+Initializing logging is only necessary once when running an application.
+Logging is already initialized automatically for the entire API, so any new
+endpoints or features built into the API don't require the above configuration.
+
+If you just want to be able to writes logs, you usually only need to do:
+
+```py
+import logging
+
+logger = logging.getLogger(__name__)
+
+def my_function():
+    logger.info("hello")
+```
+
 ## Formatting
 
 We have two separate ways of formatting the logs which are controlled by the `LOG_FORMAT` environment variable.
@@ -35,13 +68,81 @@ We have two separate ways of formatting the logs which are controlled by the `LO
 
 The [src.logging.flask_logger](../../../api/src/logging/flask_logger.py) module adds logging functionality to Flask applications. It automatically adds useful data from the Flask request object to logs, logs the start and end of requests, and provides a mechanism for developers to dynamically add extra data to all subsequent logs for the current request.
 
+For example, if you would like to add the `opportunity_id` to every log message during the lifecycle of a request, then you can do:
+```py
+import logging
+
+from src.logging.flask_logger import add_extra_data_to_current_request_logs
+
+logger = logging.getLogger(__name__)
+
+# Assume API decorators here
+def opportunity_get(opportunity_id: int):
+
+    add_extra_data_to_current_request_logs({"request.path.opportunity_id": opportunity_id})
+
+    logger.info("Example log 1")
+
+    # ... some code
+
+    logger.info("Example log 2")
+```
+
+This would produce two log messages, which would both have `request.path.opportunity_id=<the opportunity_id>` in the extra
+information of the log message. This function can be called multiple times, adding more information each time.
+
+NOTE: Be careful where you place the call to this method as it requires you to be in a Flask request context (ie. reached via calling Flask)
+If you want to test a piece of code that calls `add_extra_data_to_current_request_logs` without going via Flask, you'll either need to restructure
+the code, or 
+
+## Automatic request log details
+
+Several fields are automatically attached to every log message of a request regardless
+of what you configure in the [flask_logger](../../../api/src/logging/flask_logger.py). This includes:
+* Request ID
+* Request method (eg. `POST` or `PATCH`)
+* Request path
+* Request URL rule
+* Cognito ID from the `Cognito-Id` header
+
+Additionally when a request ends, the following will always be logged:
+* Status code
+* Content length
+* Content type
+* Mimetype
+* Request duration in milliseconds
+
 ## PII Masking
 
 The [src.logging.pii](../../../api/src/logging/pii.py) module defines a filter that applies to all logs that automatically masks data fields that look like social security numbers.
 
 ## Audit Logging
 
-* The [src.logging.audit](../../../api/src/logging/audit.py) module defines a low level audit hook that logs events that may be of interest from a security point of view, such as dynamic code execution and network requests.
+We have configured [audit logging](../../../api/src/logging/audit.py) which logs
+various events related to the process making network, file system and
+subprocess calls. This is largely done in the event we need to debug an
+issue or to detect if a library we are relying on is potentially doing
+something malicious (eg. a string parsing library shouldn't be making network requests).
+
+For more information, please review the [audit events](https://docs.python.org/3/library/audit_events.html)
+Python docs, as well as [PEP-578](https://peps.python.org/pep-0578/) which details
+the implementation details and thought process behind this feature in Python.
+
+Audit logging can be turned on/off by the `LOG_ENABLE_AUDIT` environment variable
+which is defaulted off for local development as audit logs are very verbose
+
+We don't log 100% of audit events as they are very verbose. The first 10 events
+of a particular type will all log, but after than only every 10th will log, and
+once it has reached 100 occurrences, only every 100th. This count will only
+consider the 128 most recently logged scenarios where a scenario is based on the
+call + arguments (ie. calls to the request library for different URLs are treated separately)
+
+### Audit Logging Tests
+
+The audit logging unit tests that we have written are run separately
+from the rest of the tests as enabling audit logging causes several hundred
+log messages to appear when run with everything else, and makes it very difficult
+to debug and fix your tests.
 
 ## Additional Reading