From ea892cdd9ae6f01a659e79a85c3e55d448becbd8 Mon Sep 17 00:00:00 2001
From: Juha Louhiranta <juha.louhiranta@anders.fi>
Date: Wed, 23 Jun 2021 16:16:25 +0300
Subject: [PATCH] Log ticketing system API calls for debugging

Refs MAAS-109
---
 .../tests/snapshots/snap_test_api_call.py     |  8 ++++++
 bookings/tests/test_api_call.py               | 27 +++++++++++++++++--
 bookings/ticketing_system.py                  |  8 ++++++
 3 files changed, 41 insertions(+), 2 deletions(-)

diff --git a/bookings/tests/snapshots/snap_test_api_call.py b/bookings/tests/snapshots/snap_test_api_call.py
index cc996f9..b09daab 100644
--- a/bookings/tests/snapshots/snap_test_api_call.py
+++ b/bookings/tests/snapshots/snap_test_api_call.py
@@ -13,6 +13,10 @@
     "transaction_id": "transactionID",
 }
 
+snapshots[
+    "test_api_call_for_confirmation 2"
+] = 'Ticketing system API call - URL: https://api.example.com/test_confirmation_id/confirm/ data: {"request_id": "requestID", "transaction_id": "transactionID", "locale": "fi", "maas_operator_id": "identifier of maas operator 1"}'  # noqa: E501
+
 snapshots["test_api_call_for_reservation 1"] = {
     "departures": [{"date": "2021-04-28", "trip_id": "source_id of trip 1"}],
     "locale": "fi",
@@ -27,3 +31,7 @@
     ],
     "transaction_id": "transactionID",
 }
+
+snapshots[
+    "test_api_call_for_reservation 2"
+] = 'Ticketing system API call - URL: https://api.example.com data: {"request_id": "requestID", "transaction_id": "transactionID", "locale": "fi", "maas_operator_id": "identifier of maas operator 1", "route_id": "source_id of route 1", "departures": [{"trip_id": "source_id of trip 1", "date": "2021-04-28"}], "tickets": [{"ticket_type_id": "source_id of test fare 1", "customer_type_id": "source_id of test rider category 1"}]}'  # noqa: E501
diff --git a/bookings/tests/test_api_call.py b/bookings/tests/test_api_call.py
index 6e9882f..79c9fdf 100644
--- a/bookings/tests/test_api_call.py
+++ b/bookings/tests/test_api_call.py
@@ -1,3 +1,4 @@
+import logging
 from urllib.parse import quote, urljoin
 
 import pytest
@@ -10,11 +11,25 @@
 from mock_ticket_api.utils import get_confirmations_data, get_reservation_data
 
 
+def get_log_records(caplog):
+    """Return api call log messages.
+
+    Format of record tuples is (logger_name, log_level, message).
+    """
+    return [
+        log[2]
+        for log in caplog.record_tuples
+        if log[0] == "bookings.ticketing_system" and log[1] == logging.INFO
+    ]
+
+
 @pytest.mark.django_db
 def test_api_call_for_reservation(
-    maas_operator, fare_test_data, requests_mock, snapshot
+    maas_operator, fare_test_data, requests_mock, snapshot, caplog
 ):
     ticketing_system = fare_test_data.feed.ticketing_system
+    ticketing_system.api_url = "https://api.example.com"
+    ticketing_system.save()
     requests_mock.post(
         ticketing_system.api_url,
         json=get_reservation_data(),
@@ -35,14 +50,17 @@ def test_api_call_for_reservation(
     }
 
     Booking.objects.create_reservation(maas_operator, ticketing_system, ticket_data)
+    log_messages = get_log_records(caplog)
 
     assert requests_mock.call_count == 1
     snapshot.assert_match(requests_mock.request_history[0].json())
     assert requests_mock.request_history[0].headers["Authorization"] == "Bearer APIKEY"
+    assert len(log_messages) == 1
+    snapshot.assert_match(log_messages[0])
 
 
 @pytest.mark.django_db
-def test_api_call_for_confirmation(maas_operator, requests_mock, snapshot):
+def test_api_call_for_confirmation(maas_operator, requests_mock, snapshot, caplog):
     feed = get_feed_for_maas_operator(maas_operator, True)
     extra_params = {
         "locale": "fi",
@@ -56,6 +74,8 @@ def test_api_call_for_confirmation(maas_operator, requests_mock, snapshot):
         ticketing_system=feed.ticketing_system,
     )
     ticketing_system = feed.ticketing_system
+    ticketing_system.api_url = "https://api.example.com"
+    ticketing_system.save()
     requests_mock.post(
         urljoin(ticketing_system.api_url, f"{reserved_booking.source_id}/confirm/"),
         json=get_confirmations_data(reserved_booking.source_id, include_qr=False),
@@ -63,10 +83,13 @@ def test_api_call_for_confirmation(maas_operator, requests_mock, snapshot):
     )
 
     reserved_booking.confirm(passed_parameters=extra_params)
+    log_messages = get_log_records(caplog)
 
     assert requests_mock.call_count == 1
     snapshot.assert_match(requests_mock.request_history[0].json())
     assert requests_mock.request_history[0].headers["Authorization"] == "Bearer APIKEY"
+    assert len(log_messages) == 1
+    snapshot.assert_match(log_messages[0])
 
 
 @pytest.mark.django_db
diff --git a/bookings/ticketing_system.py b/bookings/ticketing_system.py
index 4e71b2d..97c99da 100644
--- a/bookings/ticketing_system.py
+++ b/bookings/ticketing_system.py
@@ -1,3 +1,5 @@
+import json
+import logging
 from json import JSONDecodeError
 from typing import Optional
 from urllib.parse import quote, urljoin
@@ -11,6 +13,8 @@
 from .choices import BookingStatus
 from .utils import TokenAuth
 
+logger = logging.getLogger(__name__)
+
 reservation_error_codes = (
     "MAX_CAPACITY_EXCEEDED",
     "MAX_NUMBER_OF_TICKETS_REQUESTED_EXCEEDED",
@@ -107,6 +111,10 @@ def _post(self, url: str, data, success_serializer, error_serializer):
         if not self.ticketing_system.api_key:
             raise Exception("Ticketing system doesn't define an API key.")
 
+        logger.info(
+            f"Ticketing system API call - URL: {url} data: {json.dumps(payload)}"
+        )
+
         response = requests.post(
             url,
             json=payload,