Add upstream FHIR logging (#71)

* Rework log formatting

* Log time until response

* Fixup decimal formatting

sof_wrapper/api/fhir.py

@@ -47,8 +47,11 @@ def emr_meds(emr_url, params, headers):
         headers=upstream_headers,
     )
     response.raise_for_status()
-    current_app.logger.debug("emr returned {} MedicationRequests".format(
-        len(response.json().get("entry", []))))
+    current_app.logger.debug(
+        "emr returned %d MedicationRequests in %f seconds",
+        len(response.json().get("entry", [])),
+        response.elapsed.total_seconds(),
+    )
     return response.json()
 
 
@@ -139,9 +142,13 @@ def pdmp_med_orders(**kwargs):
 def pdmp_meds(pdmp_url, params):
     response = requests.get(pdmp_url, params=params)
     response.raise_for_status()
-    audit_entry("PDMP returned {} MedicationRequest/Orders".format(
-        len(response.json().get("entry", []))),
-        extra={'tags': ['PDMP', 'MedicationRequest'], 'meds': [e for e in response.json().get("entry", [])]})
+    audit_entry(
+        "PDMP facade returned {} MedicationRequest/Orders in {} seconds".format(
+            len(response.json().get("entry", [])),
+            response.elapsed.total_seconds(),
+        ),
+        extra={'tags': ['PDMP', 'MedicationRequest'], 'meds': [e for e in response.json().get("entry", [])]}
+    )
     return response.json()
 
 
@@ -226,6 +233,7 @@ def patient_by_id(id):
         headers=upstream_headers,
     )
     response.raise_for_status()
+    current_app.logger.debug("returned Patient in %f seconds", response.elapsed.total_seconds())
     patient_fhir = response.json()
     # TODO when possible w/o session cookie: set_session_value(key, patient_fhir)
 
@@ -273,6 +281,11 @@ def route_fhir(relative_path, session_id):
         params=request.args,
     )
     upstream_response.raise_for_status()
+    current_app.logger.debug(
+        "FHIR server returned %s in %f seconds",
+        relative_path,
+        upstream_response.elapsed.total_seconds(),
+    )
     return upstream_response.json()