diff --git a/lanforge_client/api_logger.py b/lanforge_client/api_logger.py new file mode 100644 index 000000000..7a03e3528 --- /dev/null +++ b/lanforge_client/api_logger.py @@ -0,0 +1,141 @@ +""" +Process-wide, opt-in CSV logging of LANforge API calls (GET/POST/PUT/DELETE), for +debugging a particular test run. + +Call configure_api_call_logging() once, near the start of a script; every API call +made afterward in the same process is then recorded automatically. +""" +import csv +import datetime +import json +import logging +from pathlib import Path +from typing import Any, Optional + +logger = logging.getLogger(__name__) + +# CSV header for API call logs with prefixed column names to avoid ambiguity across reports. +CSV_FIELDS = ['api_timestamp', 'api_method', 'api_url', 'api_status', 'api_response_code', + 'api_elapsed_ms', 'api_payload', 'api_error', 'api_diagnostics'] + +_logging_enabled = False +_logging_paused = False +_log_filename = None + + +def configure_api_call_logging(enabled: bool, log_filename: Optional[str] = None) -> None: + """ + Enable or disable process-wide API-call logging. + + Args: + enabled: True to turn logging on, False to turn it off. + log_filename: Path to the CSV log file; defaults to ~/lf_api_calls.csv when not set. + + Returns: + None. + """ + global _logging_enabled, _log_filename, _logging_paused + _logging_enabled = bool(enabled) + _logging_paused = False + if not _logging_enabled: + return + _log_filename = log_filename or str(Path.home() / 'lf_api_calls.csv') + # start each run with a clean log file + try: + with open(_log_filename, 'w', newline='') as csv_file: + csv.writer(csv_file).writerow(CSV_FIELDS) + except Exception as x: + logger.debug("api_logger: unable to reset %s: %s" % (_log_filename, x)) + + +def pause() -> None: + """ + Temporarily stop recording API calls until resume() is called. + + Returns: + None. + """ + global _logging_paused + _logging_paused = True + + +def resume() -> None: + """ + Resume recording API calls after pause(). + + Returns: + None. + """ + global _logging_paused + _logging_paused = False + + +def is_enabled() -> bool: + """ + Check whether API-call logging is currently enabled. + + Returns: + True if logging is enabled, False otherwise. + """ + return _logging_enabled + + +def get_log_filename() -> Optional[str]: + """ + Get the path of the API-call log CSV file. + + Returns: + The log file path, or None if logging has not been configured. + """ + return _log_filename + + +def record_api_call(method: str, url: str, data: Optional[Any] = None, response_code: Optional[int] = None, + error: Optional[Exception] = None, diagnostics: Optional[str] = None, + sent_at: Optional[datetime.datetime] = None, + elapsed_ms: Optional[float] = None) -> None: + """ + Append one CSV row for a json_get/json_post/json_put/json_delete call. No-op unless + configure_api_call_logging(enabled=True) was called first, or while paused (see pause()/resume()). + + Args: + method: "GET" | "POST" | "PUT" | "DELETE". + url: Requested url. + data: Payload sent (POST/PUT only). + response_code: HTTP status code returned by the call, if any. + error: Exception raised by the call, if any -- marks the entry as ERROR. + diagnostics: One-line summary from LFRequest.print_diagnostics(), if the call + went through a caught HTTPError/URLError (reason, X-Error-* headers, etc.) + sent_at: Timestamp captured by the caller right before the request was issued. + Falls back to datetime.now() (this function's call time) when not provided, + which is captured well after the request completed and is less accurate. + elapsed_ms: Wall-clock duration of the underlying urlopen() call in milliseconds, + measured by the caller with time.perf_counter() around just the request itself + (excludes diagnostics/logging overhead). None when not measured. + + Returns: + None. + """ + if not _logging_enabled or _logging_paused: + return + if error: + status = "ERROR" + elif response_code: + status = "OK" if 200 <= response_code < 300 else "ERROR" + else: + status = "UNKNOWN" + try: + with open(_log_filename, 'a', newline='') as csv_file: + csv.writer(csv_file).writerow([ + (sent_at or datetime.datetime.now()).isoformat(), + method, + url, + status, + response_code if response_code is not None else 'No response_code', + round(elapsed_ms, 3) if elapsed_ms is not None else 'Unknown', + json.dumps(data, default=str) if data is not None else '-', + error, + diagnostics if diagnostics is not None else 'No diagnostics', + ]) + except Exception as x: + logger.debug("api_logger: unable to write %s: %s" % (_log_filename, x)) diff --git a/lanforge_client/lanforge_api.py b/lanforge_client/lanforge_api.py index e655336a6..d7033c732 100644 --- a/lanforge_client/lanforge_api.py +++ b/lanforge_client/lanforge_api.py @@ -101,6 +101,7 @@ class which appends subclasses to it. # - - - - deployed import references - - - - - from .strutil import nott, iss +from . import api_logger SESSION_HEADER = 'X-LFJson-Session' # LOGGER = Logger('json_api') @@ -173,6 +174,10 @@ def print_diagnostics(url_: str = None, error_list_.append(xerr) LOGGER.error(" = = = = = = = = = = = = = = = =") + summary = "%s <%s> HTTP %s: %s" % (method, err_full_url, err_code, err_reason) + if xerrors and err_code != 404: + summary += " | " + "; ".join(xerrors) + if error_.__class__ is urllib.error.HTTPError: LOGGER.debug("----- HTTPError: ------------------------------------ print_diagnostics:") LOGGER.debug("%s <%s> HTTP %s: %s" % (method, err_full_url, err_code, err_reason)) @@ -203,7 +208,7 @@ def print_diagnostics(url_: str = None, LOGGER.warning("------------------------------------------------------------------------") if die_on_error_: exit(1) - return + return summary if error_.__class__ is urllib.error.URLError: LOGGER.error("----- URLError: ---------------------------------------------") @@ -212,6 +217,8 @@ def print_diagnostics(url_: str = None, if die_on_error_: exit(1) + return summary + class BaseLFJsonRequest: """----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- @@ -573,9 +580,12 @@ def json_post(self, finish_time_ms = (max_timeout_sec * 1000) + begin_time_ms attempt = 1 while (time.time() * 1000) < finish_time_ms: + sent_at = datetime.now() + _t0 = time.perf_counter() try: response = urllib.request.urlopen(myrequest) resp_data = response.read().decode('utf-8') + elapsed_ms = (time.perf_counter() - _t0) * 1000 if self.receives_async_feedback and (response_json_list is None and resp_data): self.logger.warning("json_post: POST to URL has data: " + url) raise ValueError("json_post: not returning post data, no response_json_list provided") @@ -635,37 +645,52 @@ def json_post(self, self.logger.debug("----------------- BAD STATUS --------------------------------") if die_on_error: sys.exit(1) + api_logger.record_api_call(method=method_, url=url, data=post_data, response_code=response.status, + sent_at=sent_at, elapsed_ms=elapsed_ms) return responses[0] except urllib.error.HTTPError as herror: + elapsed_ms = (time.perf_counter() - _t0) * 1000 # these error codes illustrate an error on the client that requires debugging # and retrying them is never going to succeed if herror.code in (400, 410, 411, 412, 413, 414, 415, 416, 417, 428, 429, 431, 451): die_on_error = True - print_diagnostics(url_=url, + # die_on_error_=False here: we want to log the call before exiting, so the + # sys.exit(1) below (not print_diagnostics' own) is what actually exits + diagnostics = print_diagnostics(url_=url, request_=myrequest, responses_=responses, error_=herror, debug_=debug, - die_on_error_=die_on_error) + die_on_error_=False) + api_logger.record_api_call(method=method_, url=url, data=post_data, response_code=herror.code, + error=herror, diagnostics=diagnostics, sent_at=sent_at, + elapsed_ms=elapsed_ms) if die_on_error: sys.exit(1) except urllib.error.URLError as uerror: + elapsed_ms = (time.perf_counter() - _t0) * 1000 # this is a misformatted URL die_on_error = True if (url.endswith("endsession")): logging.info("lfclient closed connection before script exit") + api_logger.record_api_call(method=method_, url=url, data=post_data, error=uerror, + diagnostics="session ended", sent_at=sent_at, + elapsed_ms=elapsed_ms) die_on_error = True break else: logging.error("Connection refused: "+url) - print_diagnostics(url_=url, + diagnostics = print_diagnostics(url_=url, request_=myrequest, responses_=responses, error_=uerror, debug_=debug, - die_on_error_=die_on_error) + die_on_error_=False) + api_logger.record_api_call(method=method_, url=url, data=post_data, error=uerror, + diagnostics=diagnostics, sent_at=sent_at, + elapsed_ms=elapsed_ms) if die_on_error: sys.exit(1) # ~while @@ -798,28 +823,42 @@ def get(self, myrequest.timeout = connection_timeout_sec myresponses: list = [] # list[HTTPResponse] + sent_at = datetime.now() + _t0 = time.perf_counter() try: myresponses.append(request.urlopen(myrequest)) + elapsed_ms = (time.perf_counter() - _t0) * 1000 + api_logger.record_api_call(method=method_, url=requested_url, response_code=myresponses[0].status, + sent_at=sent_at, elapsed_ms=elapsed_ms) return myresponses[0] except urllib.error.HTTPError as herror: - print_diagnostics(url_=requested_url, + elapsed_ms = (time.perf_counter() - _t0) * 1000 + # die_on_error_=False here: we want to log the call before exiting, so the + # sys.exit(1) below (not print_diagnostics' own) is what actually exits + diagnostics = print_diagnostics(url_=requested_url, request_=myrequest, responses_=myresponses, error_=herror, error_list_=self.error_list, debug_=debug, - die_on_error_=die_on_error) + die_on_error_=False) + api_logger.record_api_call(method=method_, url=requested_url, response_code=herror.code, + error=herror, diagnostics=diagnostics, sent_at=sent_at, + elapsed_ms=elapsed_ms) if die_on_error: sys.exit(1) except urllib.error.URLError as uerror: - print_diagnostics(url_=requested_url, + elapsed_ms = (time.perf_counter() - _t0) * 1000 + diagnostics = print_diagnostics(url_=requested_url, request_=myrequest, responses_=myresponses, error_=uerror, error_list_=self.error_list, debug_=debug, - die_on_error_=die_on_error) + die_on_error_=False) + api_logger.record_api_call(method=method_, url=requested_url, error=uerror, diagnostics=diagnostics, + sent_at=sent_at, elapsed_ms=elapsed_ms) if die_on_error: sys.exit(1) if die_on_error: diff --git a/py-json/LANforge/LFRequest.py b/py-json/LANforge/LFRequest.py index 981453541..30b85625a 100644 --- a/py-json/LANforge/LFRequest.py +++ b/py-json/LANforge/LFRequest.py @@ -7,6 +7,8 @@ import logging import sys import os +import time +from datetime import datetime from pprint import pformat, PrettyPrinter import urllib from urllib import request @@ -41,6 +43,10 @@ def __init__(self, url=None, self.debug = debug_ self.die_on_error = die_on_error_ self.error_list = [] + self.last_response_code = None + self.last_diagnostics = None + self.last_sent_at = None + self.last_elapsed_ms = None # please see this discussion on ProxyHandlers: # https://docs.python.org/3/library/urllib.request.html#urllib.request.ProxyHandler @@ -183,8 +189,12 @@ def json_post(self, show_error=True, debug=False, die_on_error_=False, response_ # https://stackoverflow.com/a/59635684/11014343 + self.last_sent_at = datetime.now() + _t0 = time.perf_counter() try: resp = urllib.request.urlopen(myrequest) + self.last_elapsed_ms = (time.perf_counter() - _t0) * 1000 + self.last_response_code = getattr(resp, 'status', None) resp_data = resp.read().decode('utf-8') if debug or die_on_error_: self.logger.debug("----- LFRequest::json_post:128 debug: --------------------------------------------") @@ -208,18 +218,21 @@ def json_post(self, show_error=True, debug=False, die_on_error_=False, response_ return responses[0] except urllib.error.HTTPError as error: - print_diagnostics(url_=self.requested_url, - request_=myrequest, - responses_=responses, - error_=error, - debug_=debug) + self.last_elapsed_ms = (time.perf_counter() - _t0) * 1000 + self.last_response_code = error.code + self.last_diagnostics = print_diagnostics(url_=self.requested_url, + request_=myrequest, + responses_=responses, + error_=error, + debug_=debug) except urllib.error.URLError as uerror: - print_diagnostics(url_=self.requested_url, - request_=myrequest, - responses_=responses, - error_=uerror, - debug_=debug) + self.last_elapsed_ms = (time.perf_counter() - _t0) * 1000 + self.last_diagnostics = print_diagnostics(url_=self.requested_url, + request_=myrequest, + responses_=responses, + error_=uerror, + debug_=debug) if die_on_error_: exit(1) @@ -249,25 +262,31 @@ def get(self, method_='GET'): headers=self.default_headers, method=method_) myresponses = [] + self.last_sent_at = datetime.now() + _t0 = time.perf_counter() try: myresponses.append(request.urlopen(myrequest)) + self.last_elapsed_ms = (time.perf_counter() - _t0) * 1000 return myresponses[0] except urllib.error.HTTPError as error: - print_diagnostics(url_=self.requested_url, - request_=myrequest, - responses_=myresponses, - error_=error, - error_list_=self.error_list, - debug_=self.debug) + self.last_elapsed_ms = (time.perf_counter() - _t0) * 1000 + self.last_response_code = error.code + self.last_diagnostics = print_diagnostics(url_=self.requested_url, + request_=myrequest, + responses_=myresponses, + error_=error, + error_list_=self.error_list, + debug_=self.debug) except urllib.error.URLError as uerror: - print_diagnostics(url_=self.requested_url, - request_=myrequest, - responses_=myresponses, - error_=uerror, - error_list_=self.error_list, - debug_=self.debug) + self.last_elapsed_ms = (time.perf_counter() - _t0) * 1000 + self.last_diagnostics = print_diagnostics(url_=self.requested_url, + request_=myrequest, + responses_=myresponses, + error_=uerror, + error_list_=self.error_list, + debug_=self.debug) if self.die_on_error: exit(1) @@ -279,6 +298,10 @@ def getAsJson(self): def get_as_json(self, method_='GET'): responses = list() responses.append(self.get(method_=method_)) + # get() already stashes last_response_code from error.code on HTTPError; + # only overwrite it here when we actually have a response to read a status from + if responses[0]: + self.last_response_code = getattr(responses[0], 'status', None) if len(responses) < 1: if self.debug and self.has_errors(): self.print_errors() @@ -350,6 +373,21 @@ def plain_get(url_=None, debug_=False, die_on_error_=False, proxies_=None): def print_diagnostics(url_=None, request_=None, responses_=None, error_=None, error_list_=None, debug_=False): + """ + Log a diagnostic report for a failed request and return a one-line summary of it. + + Args: + url_: Requested url. + request_: The urllib Request object that was sent. + responses_: Responses collected so far for this request, if any. + error_: The caught urllib.error.HTTPError or URLError. + error_list_: Optional list to append LANforge X-Error-* messages to. + debug_: When True, log at debug level; error level otherwise. + + Returns: + A short one-line summary of the error (code/reason/X-Error-* headers), for callers + (like LFRequest._log_api_call plumbing) that want it in a lightweight log. + """ logger = logging.getLogger(__name__) # logger.error("LFRequest::print_diagnostics: error_.__class__: %s"%error_.__class__) # logger.error(pformat(error_)) @@ -395,6 +433,10 @@ def print_diagnostics(url_=None, request_=None, responses_=None, error_=None, er errors_list.append(" = = = = = = = = = = = = = = = =") logger.error("\n".join(errors_list)) + summary = "%s <%s> HTTP %s: %s" % (method, err_full_url, err_code, err_reason) + if xerrors and err_code != 404: + summary += " | " + "; ".join(xerrors) + if error_.__class__ is urllib.error.HTTPError: debug_list = [] debug_list.append("\n----- LFRequest: HTTPError: --------------------------------------------") @@ -425,11 +467,13 @@ def print_diagnostics(url_=None, request_=None, responses_=None, error_=None, er debug_list.append("------------------------------------------------------------------------") logger.debug("\n".join(debug_list)) - return + return summary if error_.__class__ is urllib.error.URLError: errors_list.append("\n----- LFRequest: URLError: ---------------------------------------------") errors_list.append("%s <%s> HTTP %s: %s" % (method, err_full_url, err_code, err_reason)) errors_list.append("------------------------------------------------------------------------") logger.error("\n".join(errors_list)) + + return summary # ~LFRequest diff --git a/py-json/LANforge/lfcli_base.py b/py-json/LANforge/lfcli_base.py index 34d4085a8..e2fcfee53 100644 --- a/py-json/LANforge/lfcli_base.py +++ b/py-json/LANforge/lfcli_base.py @@ -14,6 +14,7 @@ import re import logging import math +from typing import Any, Optional if sys.version_info[0] != 3: print("This script requires Python 3") @@ -25,6 +26,7 @@ LFRequest = importlib.import_module("py-json.LANforge.LFRequest") LFUtils = importlib.import_module("py-json.LANforge.LFUtils") Logg = importlib.import_module("lanforge_client.logg") +api_logger = importlib.import_module("lanforge_client.api_logger") logger = logging.getLogger(__name__) """ @@ -216,6 +218,33 @@ def log_set_filename(filename=None): # - END LOGGING - + def _log_api_call(self, method: str, url: str, data: Optional[Any] = None, response_code: Optional[int] = None, + error: Optional[Exception] = None, diagnostics: Optional[str] = None, + sent_at: Optional[datetime.datetime] = None, + elapsed_ms: Optional[float] = None) -> None: + """ + Record one json_get/json_post/json_put/json_delete call via lanforge_client.api_logger. + + Args: + method: "GET" | "POST" | "PUT" | "DELETE". + url: Requested url. + data: Payload sent (POST/PUT only). + response_code: HTTP status code returned by the call, if any. + error: Exception raised by the call, if any. + diagnostics: One-line diagnostics summary, if the call went through a caught error. + sent_at: Timestamp captured by LFRequest right before the request was issued + (its last_sent_at attribute); falls back to record_api_call's own call time + when not available. + elapsed_ms: Wall-clock duration of the underlying urlopen() call in milliseconds + (LFRequest's last_elapsed_ms attribute). None when not measured. + + Returns: + None. + """ + api_logger.record_api_call(method=method, url=url, data=data, response_code=response_code, + error=error, diagnostics=diagnostics, sent_at=sent_at, + elapsed_ms=elapsed_ms) + def json_post(self, _req_url, _data, debug_=False, suppress_related_commands_=None, response_json_list_=None): """ send json to the LANforge client @@ -227,6 +256,8 @@ def json_post(self, _req_url, _data, debug_=False, suppress_related_commands_=No :return: http response object """ json_response = None + _api_error = None + lf_r = None debug_ |= self.debug try: lf_r = LFRequest.LFRequest(url=self.lfclient_url, @@ -264,13 +295,24 @@ def json_post(self, _req_url, _data, debug_=False, suppress_related_commands_=No if debug_ and (response_json_list_ is not None): logger.debug(pprint.pformat(response_json_list_)) except Exception as x: + _api_error = x if debug_ or self.exit_on_error: logger.debug("json_post posted to %s" % _req_url) logger.debug(pprint.pformat(_data)) logger.debug("Exception %s:" % x) logger.debug(traceback.format_exception(Exception, x, x.__traceback__, chain=True)) if self.exit_on_error: + self._log_api_call("POST", _req_url, data=_data, + response_code=getattr(json_response, 'status', None) or getattr(lf_r, 'last_response_code', None), + error=_api_error, diagnostics=getattr(lf_r, 'last_diagnostics', None), + sent_at=getattr(lf_r, 'last_sent_at', None), + elapsed_ms=getattr(lf_r, 'last_elapsed_ms', None)) exit(1) + self._log_api_call("POST", _req_url, data=_data, + response_code=getattr(json_response, 'status', None) or getattr(lf_r, 'last_response_code', None), + error=_api_error, diagnostics=getattr(lf_r, 'last_diagnostics', None), + sent_at=getattr(lf_r, 'last_sent_at', None), + elapsed_ms=getattr(lf_r, 'last_elapsed_ms', None)) return json_response def json_put(self, _req_url, _data, debug_=False, response_json_list_=None): @@ -286,6 +328,8 @@ def json_put(self, _req_url, _data, debug_=False, response_json_list_=None): """ debug_ |= self.debug json_response = None + _api_error = None + lf_r = None try: lf_r = LFRequest.LFRequest(url=self.lfclient_url, uri=_req_url, @@ -302,13 +346,24 @@ def json_put(self, _req_url, _data, debug_=False, response_json_list_=None): if debug_ and (response_json_list_ is not None): pprint.pprint(response_json_list_) except Exception as x: + _api_error = x if debug_ or self.exit_on_error: logger.debug("json_put submitted to %s" % _req_url) logger.debug(pprint.pformat(_data)) logger.debug("Exception %s:" % x) logger.debug(traceback.format_exception(Exception, x, x.__traceback__, chain=True)) if self.exit_on_error: + self._log_api_call("PUT", _req_url, data=_data, + response_code=getattr(json_response, 'status', None) or getattr(lf_r, 'last_response_code', None), + error=_api_error, diagnostics=getattr(lf_r, 'last_diagnostics', None), + sent_at=getattr(lf_r, 'last_sent_at', None), + elapsed_ms=getattr(lf_r, 'last_elapsed_ms', None)) exit(1) + self._log_api_call("PUT", _req_url, data=_data, + response_code=getattr(json_response, 'status', None) or getattr(lf_r, 'last_response_code', None), + error=_api_error, diagnostics=getattr(lf_r, 'last_diagnostics', None), + sent_at=getattr(lf_r, 'last_sent_at', None), + elapsed_ms=getattr(lf_r, 'last_elapsed_ms', None)) return json_response def json_get(self, _req_url, debug_=None): @@ -319,6 +374,8 @@ def json_get(self, _req_url, debug_=None): if debug_ is None: debug_ = self.debug json_response = None + _api_error = None + lf_r = None try: lf_r = LFRequest.LFRequest(url=self.lfclient_url, uri=_req_url, @@ -334,15 +391,28 @@ def json_get(self, _req_url, debug_=None): else: logger.debug("LFCliBase.json_get: no entity/response, check other errors") time.sleep(10) + self._log_api_call("GET", _req_url, response_code=getattr(lf_r, 'last_response_code', None), + diagnostics=getattr(lf_r, 'last_diagnostics', None), + sent_at=getattr(lf_r, 'last_sent_at', None), + elapsed_ms=getattr(lf_r, 'last_elapsed_ms', None)) return None except ValueError as ve: + _api_error = ve if debug_ or self.exit_on_error: logger.debug("jsonGet asked for {_req_url} ".format(_req_url=_req_url)) logger.debug("Exception %s:" % ve) logger.debug(traceback.format_exception(ValueError, ve, ve.__traceback__, chain=True)) if self.exit_on_error: + self._log_api_call("GET", _req_url, response_code=getattr(lf_r, 'last_response_code', None), error=_api_error, + diagnostics=getattr(lf_r, 'last_diagnostics', None), + sent_at=getattr(lf_r, 'last_sent_at', None), + elapsed_ms=getattr(lf_r, 'last_elapsed_ms', None)) sys.exit(1) + self._log_api_call("GET", _req_url, response_code=getattr(lf_r, 'last_response_code', None), error=_api_error, + diagnostics=getattr(lf_r, 'last_diagnostics', None), + sent_at=getattr(lf_r, 'last_sent_at', None), + elapsed_ms=getattr(lf_r, 'last_elapsed_ms', None)) return json_response def json_delete(self, _req_url, debug_=False): @@ -350,6 +420,8 @@ def json_delete(self, _req_url, debug_=False): if debug_: logger.debug("DELETE: {_req_url}".format(_req_url=_req_url)) json_response = None + _api_error = None + lf_r = None try: # logger.info("----- DELETE ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ") lf_r = LFRequest.LFRequest(url=self.lfclient_url, @@ -362,15 +434,28 @@ def json_delete(self, _req_url, debug_=False): # logger.debug(debug_printer.pformat(json_response)) if (json_response is None) and debug_: logger.debug("LFCliBase.json_delete: no entity/response, probabily status 404") + self._log_api_call("DELETE", _req_url, response_code=getattr(lf_r, 'last_response_code', None), + diagnostics=getattr(lf_r, 'last_diagnostics', None), + sent_at=getattr(lf_r, 'last_sent_at', None), + elapsed_ms=getattr(lf_r, 'last_elapsed_ms', None)) return None except ValueError as ve: + _api_error = ve if debug_ or self.exit_on_error: logger.debug("json_delete asked for {_req_url}".format(_req_url=_req_url)) logger.debug("Exception %s:" % ve) logger.debug(traceback.format_exception(ValueError, ve, ve.__traceback__, chain=True)) if self.exit_on_error: + self._log_api_call("DELETE", _req_url, response_code=getattr(lf_r, 'last_response_code', None), error=_api_error, + diagnostics=getattr(lf_r, 'last_diagnostics', None), + sent_at=getattr(lf_r, 'last_sent_at', None), + elapsed_ms=getattr(lf_r, 'last_elapsed_ms', None)) sys.exit(1) # print("----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ----- ") + self._log_api_call("DELETE", _req_url, response_code=getattr(lf_r, 'last_response_code', None), error=_api_error, + diagnostics=getattr(lf_r, 'last_diagnostics', None), + sent_at=getattr(lf_r, 'last_sent_at', None), + elapsed_ms=getattr(lf_r, 'last_elapsed_ms', None)) return json_response @staticmethod diff --git a/py-scripts/lf_webpage.py b/py-scripts/lf_webpage.py index 212c6b106..ca9cb8a19 100755 --- a/py-scripts/lf_webpage.py +++ b/py-scripts/lf_webpage.py @@ -131,6 +131,7 @@ realm = importlib.import_module("py-json.realm") Realm = realm.Realm PortUtils = realm.PortUtils +api_logger = importlib.import_module("lanforge_client.api_logger") lf_report = importlib.import_module("py-scripts.lf_report") lf_graph = importlib.import_module("py-scripts.lf_graph") lf_kpi_csv = importlib.import_module("py-scripts.lf_kpi_csv") @@ -154,7 +155,8 @@ def __init__(self, lfclient_host, lfclient_port, upstream, num_sta, security, ss device_list=None, get_url_from_file=None, file_path=None, device_csv_name='', expected_passfail_value=None, file_name=None, group_name=None, profile_name=None, eap_method=None, eap_identity=None, ieee80211=None, ieee80211u=None, ieee80211w=None, enable_pkc=None, bss_transition=None, power_save=None, disable_ofdma=None, roam_ft_ds=None, key_management=None, pairwise=None, private_key=None, ca_cert=None, client_cert=None, pk_passwd=None, pac_file=None, config=False, wait_time=60, get_live_view=False, total_floors=0, robot_test=False, - robot_ip=None, coordinate=None, rotation=None, duration=None, do_bandsteering=False, cycles=None, bssids=None, duration_to_skip=None): + robot_ip=None, coordinate=None, rotation=None, duration=None, do_bandsteering=False, cycles=None, bssids=None, duration_to_skip=None, + log_monitor_api_calls=False): # super().__init__(lfclient_host=lfclient_host, # lfclient_port=lfclient_port) self.ssid_list = [] @@ -190,6 +192,7 @@ def __init__(self, lfclient_host, lfclient_port, upstream, num_sta, security, ss self.ap_name = ap_name self.windows_ports = [] self.windows_eids = [] + self.log_monitor_api_calls = log_monitor_api_calls self.local_realm = realm.Realm(lfclient_host=self.host, lfclient_port=self.port) self.station_profile = self.local_realm.new_station_profile() self.http_profile = self.local_realm.new_http_profile() @@ -910,6 +913,10 @@ def monitor_for_runtime_csv(self, duration): self.monitor_start_time = datetime.now() else: self.monitor_start_time = datetime.now() + # exclude this loop's polling calls from the API log by default -- they're noisy + # and rarely what you're debugging; pass --log_monitor_api_calls to keep them + if not self.log_monitor_api_calls: + api_logger.pause() time_now = datetime.now() starttime = time_now.strftime("%d/%m %I:%M:%S %p") # duration = self.traffic_duration @@ -1126,6 +1133,8 @@ def monitor_for_runtime_csv(self, duration): except Exception: logger.error("All l4 data not found") self.actual_monitor_duration += (datetime.now() - self.monitor_start_time).total_seconds() + if not self.log_monitor_api_calls: + api_logger.resume() return test_stopped_by_user def get_all_l4_data(self): @@ -1644,6 +1653,12 @@ def generate_report(self, date, num_stations, duration, test_setup_info, dataset # To store http_datavalues.csv in report folder report_path_date_time = report.get_path_date_time() + # Copy the api log csv file (json_get/post/put/delete calls) into the report folder, if enabled + if api_logger.is_enabled(): + try: + shutil.copy(api_logger.get_log_filename(), report_path_date_time) + except Exception: + logging.info("failed to copy api log file %s to report dir" % api_logger.get_log_filename()) # It ensures no blocker for virtual clients if self.client_type == 'Real': shutil.move('http_datavalues.csv', report_path_date_time) @@ -2838,6 +2853,13 @@ def main(): optional.add_argument("--test_priority", default="", help="dut model for kpi.csv, test-priority is arbitrary number") optional.add_argument("--test_id", default="lf_webpage", help="test-id for kpi.csv, script or test name") optional.add_argument('--csv_outfile', help="--csv_outfile ", default="") + optional.add_argument('--enable_api_logging', help="save json_get/json_post/json_put/json_delete calls to a lightweight csv log file", + action="store_true", default=False) + optional.add_argument('--api_log_file_name', help="path to the api log csv file used when --enable_api_logging is set (default: ~/lf_api_calls.csv)", + default=None) + optional.add_argument('--log_monitor_api_calls', help="also record API calls made during the runtime-CSV monitor loop " + "(off by default to keep --enable_api_logging's log focused on setup/teardown calls)", + action="store_true", default=False) # ARGS for webGUI required.add_argument('--dowebgui', help="If true will execute script for webgui", default=False) # FOR WEBGUI optional.add_argument('--result_dir', @@ -2938,6 +2960,8 @@ def main(): print(help_summary) exit(0) + api_logger.configure_api_call_logging(enabled=args.enable_api_logging, log_filename=args.api_log_file_name) + args.bands.sort() # Error checking to prevent case issues @@ -3024,6 +3048,7 @@ def main(): ssid = [args.twog_ssid, args.fiveg_ssid] passwd = [args.twog_passwd, args.fiveg_passwd] http = HttpDownload(lfclient_host=args.mgr, lfclient_port=args.mgr_port, + log_monitor_api_calls=args.log_monitor_api_calls, upstream=args.upstream_port, num_sta=args.num_stations, security=security, ap_name=args.ap_name, ssid=ssid, password=passwd,