diff --git a/lanforge_client/api_call_logger.py b/lanforge_client/api_call_logger.py new file mode 100644 index 000000000..bc0693e7e --- /dev/null +++ b/lanforge_client/api_call_logger.py @@ -0,0 +1,82 @@ +#!/usr/bin/env python3 +""" +Shared, lightweight API call logger. + +This exists so any code path that talks to a LANforge GUI -- the legacy +py-json/LANforge/LFRequest.py request layer (used via LFCliBase/Realm), or +lanforge_api.py's own request layer -- can record the same kind of entry +(url, payload, response code, session id) to the same kind of rotating log +file, without each path reimplementing rotation/formatting itself. +""" +import os +import json +import logging +import logging.handlers +import datetime + +_api_loggers = {} + + +def get_api_logger(filename, max_bytes=10 * 1024 * 1024, backup_count=10): + """ + Return a cached, rotating file logger for `filename`. Callers that pass the same + filename (even from different LFCliBase/Realm instances, or a different request layer + entirely) share one logger/handler, so log lines are never duplicated and the file + rotates once instead of racing multiple independent handlers against each other. + :param filename: path to the api log file + :param max_bytes: rotate once the active file reaches this size + :param backup_count: number of rotated backups to keep + :return: a logging.Logger configured with a RotatingFileHandler + """ + key = os.path.abspath(filename) + if key in _api_loggers: + return _api_loggers[key] + api_logger = logging.getLogger("lanforge_client.api_call_logger.%s" % key) + api_logger.setLevel(logging.INFO) + api_logger.propagate = False + handler = logging.handlers.RotatingFileHandler(filename, maxBytes=max_bytes, backupCount=backup_count) + handler.setFormatter(logging.Formatter("%(message)s")) + api_logger.addHandler(handler) + _api_loggers[key] = api_logger + return api_logger + + +def log_api_call(api_logger, method, url, session_id=None, data=None, response_code=None, error=None, + diagnostics=None): + """ + Format and emit one lightweight record of an API call via api_logger. No-op if + api_logger is None, so callers can pass through a possibly-absent logger without + guarding every call site themselves. + :param api_logger: a logger from get_api_logger(), or None to skip silently + :param method: "GET" | "POST" | "PUT" | "DELETE" + :param url: requested url + :param session_id: the lanforge_api session id ("cookie") tying this call to the + LANforge GUI's own request logs, if available + :param data: payload sent (POST/PUT only) + :param response_code: HTTP status code returned by the call, if any + :param error: exception raised by the call, if any -- marks the entry as ERROR + :param diagnostics: one-line summary of a caught HTTPError/URLError (reason, + X-Error-* headers, etc.) + """ + if api_logger is None: + return + if error is not None: + status = "ERROR" + elif response_code is not None: + status = "OK" if 200 <= response_code < 300 else "ERROR" + else: + status = "UNKNOWN" + lines = ["%s session=%s %s %s [%s]" % + (datetime.datetime.now().isoformat(), session_id or '-', method, url, status)] + if data is not None: + lines.append(" payload: %s" % json.dumps(data, default=str)) + if error is not None: + lines.append(" error: %s" % error) + if response_code is not None: + lines.append(" response_code: %s" % response_code) + if diagnostics is not None: + lines.append(" diagnostics: %s" % diagnostics) + try: + api_logger.info("\n".join(lines)) + except Exception: + logging.getLogger(__name__).debug("log_api_call: unable to emit log line", exc_info=True) diff --git a/lanforge_client/lanforge_api.py b/lanforge_client/lanforge_api.py index d3ad5b411..0de8ac069 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 .api_call_logger import get_api_logger, log_api_call 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: ---------------------------------------------") @@ -211,6 +216,7 @@ def print_diagnostics(url_: str = None, LOGGER.error("------------------------------------------------------------------------") if die_on_error_: exit(1) + return summary class BaseLFJsonRequest: @@ -242,6 +248,10 @@ def __init__(self, self.session_instance = None self.stream_errors: bool = True self.stream_warnings: bool = False + # set by get()/json_post() so _log_api_call() can report the outcome of the last + # attempt even when it ended in a caught HTTPError/URLError + self.last_response_code = None + self.last_diagnostics = None if not session_obj: logging.getLogger(__name__).warning("BaseLFJsonRequest: no session instance") @@ -320,6 +330,18 @@ def add_warning(self, message: str = None): def get_errors(self) -> list: return self.error_list + def _log_api_call(self, method, url, data=None, response_code=None, diagnostics=None): + """ + Record one json_get/json_post/json_put/json_delete call via the shared + lanforge_client.api_call_logger, tagged with this session's id. No-op unless + self.session_instance.save_api is True. + """ + if not getattr(self.session_instance, 'save_api', False): + return + log_api_call(getattr(self.session_instance, '_api_logger', None), method, url, + session_id=self.session_instance.get_session_id(), + data=data, response_code=response_code, diagnostics=diagnostics) + def get_warnings(self) -> list: return self.warnings @@ -635,6 +657,8 @@ def json_post(self, self.logger.debug("----------------- BAD STATUS --------------------------------") if die_on_error: sys.exit(1) + self.last_response_code = response.status + self._log_api_call(method_, url, data=post_data, response_code=self.last_response_code) return responses[0] except urllib.error.HTTPError as herror: @@ -642,13 +666,16 @@ def json_post(self, # 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, - request_=myrequest, - responses_=responses, - error_=herror, - debug_=debug, - die_on_error_=die_on_error) + self.last_response_code = herror.code + self.last_diagnostics = print_diagnostics(url_=url, + request_=myrequest, + responses_=responses, + error_=herror, + debug_=debug, + die_on_error_=die_on_error) if die_on_error: + self._log_api_call(method_, url, data=post_data, response_code=self.last_response_code, + diagnostics=self.last_diagnostics) sys.exit(1) except urllib.error.URLError as uerror: @@ -660,17 +687,21 @@ def json_post(self, break else: logging.error("Connection refused: "+url) - print_diagnostics(url_=url, - request_=myrequest, - responses_=responses, - error_=uerror, - debug_=debug, - die_on_error_=die_on_error) + self.last_diagnostics = print_diagnostics(url_=url, + request_=myrequest, + responses_=responses, + error_=uerror, + debug_=debug, + die_on_error_=die_on_error) if die_on_error: + self._log_api_call(method_, url, data=post_data, response_code=self.last_response_code, + diagnostics=self.last_diagnostics) sys.exit(1) # ~while LOGGER.error("json_post: request will try again in 2 sec") time.sleep(2) + self._log_api_call(method_, url, data=post_data, response_code=self.last_response_code, + diagnostics=self.last_diagnostics) if die_on_error: sys.exit(1) return None @@ -800,26 +831,28 @@ def get(self, myresponses: list = [] # list[HTTPResponse] try: myresponses.append(request.urlopen(myrequest)) + self.last_response_code = getattr(myresponses[0], 'status', None) return myresponses[0] except urllib.error.HTTPError as herror: - print_diagnostics(url_=requested_url, - request_=myrequest, - responses_=myresponses, - error_=herror, - error_list_=self.error_list, - debug_=debug, - die_on_error_=die_on_error) + self.last_response_code = herror.code + self.last_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) if die_on_error: sys.exit(1) except urllib.error.URLError as uerror: - print_diagnostics(url_=requested_url, - request_=myrequest, - responses_=myresponses, - error_=uerror, - error_list_=self.error_list, - debug_=debug, - die_on_error_=die_on_error) + self.last_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) if die_on_error: sys.exit(1) if die_on_error: @@ -863,6 +896,8 @@ def get_as_json(self, if responses[0] is None: if debug: self.logger.debug(msg="No response from " + url) + self._log_api_call(method_, url, response_code=self.last_response_code, + diagnostics=self.last_diagnostics) return None json_data = json.loads(responses[0].read().decode('utf-8')) @@ -872,6 +907,8 @@ def get_as_json(self, if "warnings" in responses[0]: errors_warnings.extend(json_data["warnings"]) + self._log_api_call(method_, url, response_code=self.last_response_code, + diagnostics=self.last_diagnostics) return json_data def json_get(self, @@ -1179,10 +1216,26 @@ def __init__(self, lfclient_url: str = 'http://localhost:8080', retry_sec: float = Default_Retry_Sec, stream_errors: bool = True, stream_warnings: bool = False, - exit_on_error: bool = False): + exit_on_error: bool = False, + save_api: bool = False, + api_log_file_name: str = None, + api_log_max_bytes: int = 10 * 1024 * 1024, + api_log_backup_count: int = 10): self.debug_on = debug # self.logger = Logg(name='json_api_session') self.logger = logging.getLogger(__name__) + # when True, json_get/json_post/json_put/json_delete append a lightweight record of + # each call (url, payload, response_code/error) to api_log_filename, tagged with this + # session's id -- see lanforge_client/api_call_logger.py. The file rotates instead of + # growing unbounded, so it's safe to leave enabled indefinitely. + self.save_api = save_api + self.api_log_filename = api_log_file_name or os.path.join(os.path.expanduser('~'), 'lf_api_calls.log') + self._api_logger = None + if self.save_api: + try: + self._api_logger = get_api_logger(self.api_log_filename, api_log_max_bytes, api_log_backup_count) + except Exception as x: + self.logger.debug("BaseSession: unable to set up api logger for %s: %s" % (self.api_log_filename, x)) if debug: self.logger.level = logging.DEBUG @@ -25531,7 +25584,11 @@ def __init__(self, lfclient_url: str = 'http://localhost:8080', stream_errors: bool = True, stream_warnings: bool = False, require_session: bool = False, - exit_on_error: bool = False): + exit_on_error: bool = False, + save_api: bool = False, + api_log_file_name: str = None, + api_log_max_bytes: int = 10 * 1024 * 1024, + api_log_backup_count: int = 10): """ :param debug: turn on diagnostic information :param proxy_map: a dict with addresses of proxies to route requests through. @@ -25544,6 +25601,13 @@ def __init__(self, lfclient_url: str = 'http://localhost:8080', :param require_session: exit(1) if unable to establish a session_id :param exit_on_error: on requests failing HTTP requests on besides error 404, exit(1). This does not include failing to establish a session_id + :param save_api: when True, append a lightweight record of every json_get/json_post/ + json_put/json_delete call (url, payload, response_code/error) to api_log_file_name, + tagged with this session's id + :param api_log_file_name: path to the api log file used when save_api is True + (default: ~/lf_api_calls.log) + :param api_log_max_bytes: rotate the api log once it reaches this size + :param api_log_backup_count: number of rotated api log backups to keep """ super().__init__(lfclient_url=lfclient_url, debug=debug, @@ -25551,7 +25615,11 @@ def __init__(self, lfclient_url: str = 'http://localhost:8080', connection_timeout_sec=connection_timeout_sec, stream_errors=stream_errors, stream_warnings=stream_warnings, - exit_on_error=exit_on_error) + exit_on_error=exit_on_error, + save_api=save_api, + api_log_file_name=api_log_file_name, + api_log_max_bytes=api_log_max_bytes, + api_log_backup_count=api_log_backup_count) self.command_instance = LFJsonCommand(session_obj=self, debug=debug, exit_on_error=exit_on_error) self.session_connection_check = \ self.command_instance.start_session(debug=debug, diff --git a/py-json/LANforge/LFRequest.py b/py-json/LANforge/LFRequest.py index 981453541..878303e9f 100644 --- a/py-json/LANforge/LFRequest.py +++ b/py-json/LANforge/LFRequest.py @@ -23,6 +23,10 @@ debug_printer = PrettyPrinter(indent=2) +# must match lanforge_client.lanforge_api.SESSION_HEADER -- this is the header the LANforge +# GUI uses to correlate a REST request with a session id in its own logs +SESSION_HEADER = 'X-LFJson-Session' + class LFRequest: Default_Base_URL = "http://localhost:8080" @@ -37,10 +41,19 @@ def __init__(self, url=None, uri=None, proxies_=None, debug_=False, - die_on_error_=False): + die_on_error_=False, + session_id_=None): self.debug = debug_ self.die_on_error = die_on_error_ self.error_list = [] + self.last_response_code = None + self.last_diagnostics = None + self.session_id = session_id_ + # instance-level copy: default_headers is a class attribute (shared dict), so mutating + # it in place here would leak this instance's session id into every other LFRequest + self.default_headers = dict(LFRequest.default_headers) + if session_id_: + self.default_headers[SESSION_HEADER] = session_id_ # please see this discussion on ProxyHandlers: # https://docs.python.org/3/library/urllib.request.html#urllib.request.ProxyHandler @@ -185,6 +198,7 @@ def json_post(self, show_error=True, debug=False, die_on_error_=False, response_ try: resp = urllib.request.urlopen(myrequest) + 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 +222,19 @@ 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_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_diagnostics = print_diagnostics(url_=self.requested_url, + request_=myrequest, + responses_=responses, + error_=uerror, + debug_=debug) if die_on_error_: exit(1) @@ -254,20 +269,21 @@ def get(self, method_='GET'): 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_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_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 +295,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] is not None: + 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 +370,10 @@ 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): + """ + :return: 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 +419,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 +453,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..ed74d603d 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 +import json if sys.version_info[0] != 3: print("This script requires Python 3") @@ -25,6 +26,8 @@ LFRequest = importlib.import_module("py-json.LANforge.LFRequest") LFUtils = importlib.import_module("py-json.LANforge.LFUtils") Logg = importlib.import_module("lanforge_client.logg") +# shared with lanforge_api.py's own request layer, so both code paths log identically +api_call_logger = importlib.import_module("lanforge_client.api_call_logger") logger = logging.getLogger(__name__) """ @@ -50,7 +53,12 @@ def __init__(self, _lfjson_host, _lfjson_port, _exit_on_fail=False, _local_realm=None, _proxy_str=None, - _capture_signal_list=None): + _capture_signal_list=None, + _save_api=False, + _api_log_file_name=None, + _lf_session=None, + _api_log_max_bytes=10 * 1024 * 1024, + _api_log_backup_count=10): if _capture_signal_list is None: _capture_signal_list = [] self.fail_pref = "FAILED: " @@ -58,6 +66,26 @@ def __init__(self, _lfjson_host, _lfjson_port, self.lfclient_host = _lfjson_host self.lfclient_port = _lfjson_port self.debug = _debug + # optional lanforge_api.LFSession -- when set, its session id (the same "cookie" the + # LANforge GUI logs) is attached to every request we send and to our own log lines, + # so the two can be correlated + self._lf_session = _lf_session + # when True, json_get/json_post/json_put/json_delete append a lightweight + # record of each call (url, payload, response_code/error) to api_log_filename. + # The file rotates at _api_log_max_bytes, keeping _api_log_backup_count old copies, + # so it's safe to leave enabled indefinitely (e.g. for diagnosing customer systems) + # instead of growing forever or getting wiped on every run. + self.save_api = _save_api + self.api_log_filename = _api_log_file_name or os.path.join(os.path.expanduser('~'), 'lf_api_calls.log') + self.api_log_max_bytes = _api_log_max_bytes + self.api_log_backup_count = _api_log_backup_count + self._api_logger = None + if self.save_api: + try: + self._api_logger = api_call_logger.get_api_logger(self.api_log_filename, self.api_log_max_bytes, + self.api_log_backup_count) + except Exception as x: + logger.debug("LFCliBase: unable to set up api logger for %s: %s" % (self.api_log_filename, x)) # if (_debug): # logger.debug("LFCliBase._proxy_str: %s" % _proxy_str) self.proxy = {} @@ -216,6 +244,35 @@ def log_set_filename(filename=None): # - END LOGGING - + def _session_id(self): + """ + :return: the lanforge_api session id (the same "cookie" the LANforge GUI logs + against each REST request) if an LFSession was provided, else None. + """ + if self._lf_session is not None: + return self._lf_session.get_session_id() + return None + + def _log_api_call(self, method, url, data=None, response_code=None, error=None, diagnostics=None): + """ + Record a json_get/json_post/json_put/json_delete call via the shared + lanforge_client.api_call_logger, tagged with this instance's session id if one is + set. Only writes when self.save_api is True (self._api_logger is None otherwise, + which api_call_logger.log_api_call() treats as a no-op). + :param method: "GET" | "POST" | "PUT" | "DELETE" + :param url: requested url + :param data: payload sent (POST/PUT only) + :param response_code: HTTP status code returned by the call, if any + :param error: exception raised by the call, if any -- marks the entry as ERROR + :param diagnostics: one-line summary from LFRequest.print_diagnostics(), if the + call went through a caught HTTPError/URLError (reason, X-Error-* headers, etc.) + """ + if not self.save_api: + return + api_call_logger.log_api_call(self._api_logger, method, url, session_id=self._session_id(), + data=data, response_code=response_code, error=error, + diagnostics=diagnostics) + def json_post(self, _req_url, _data, debug_=False, suppress_related_commands_=None, response_json_list_=None): """ send json to the LANforge client @@ -227,13 +284,16 @@ 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, uri=_req_url, proxies_=self.proxy, debug_=debug_, - die_on_error_=self.exit_on_error) + die_on_error_=self.exit_on_error, + session_id_=self._session_id()) if suppress_related_commands_ is None: if 'suppress_preexec_cli' in _data: del _data['suppress_preexec_cli'] @@ -264,13 +324,20 @@ 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)) 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)) return json_response def json_put(self, _req_url, _data, debug_=False, response_json_list_=None): @@ -286,12 +353,15 @@ 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, proxies_=self.proxy, debug_=debug_, - die_on_error_=self.exit_on_error) + die_on_error_=self.exit_on_error, + session_id_=self._session_id()) lf_r.addPostData(_data) if debug_: logger.debug(debug_printer.pformat(_data)) @@ -302,13 +372,20 @@ 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)) 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)) return json_response def json_get(self, _req_url, debug_=None): @@ -319,12 +396,15 @@ 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, proxies_=self.proxy, debug_=debug_, - die_on_error_=self.exit_on_error) + die_on_error_=self.exit_on_error, + session_id_=self._session_id()) json_response = lf_r.get_as_json() if json_response is None: if debug_: @@ -334,15 +414,22 @@ 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)) 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)) 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)) return json_response def json_delete(self, _req_url, debug_=False): @@ -350,27 +437,37 @@ 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, uri=_req_url, proxies_=self.proxy, debug_=debug_, - die_on_error_=self.exit_on_error) + die_on_error_=self.exit_on_error, + session_id_=self._session_id()) json_response = lf_r.json_delete(debug=debug_, die_on_error_=False) logger.info(json_response) # 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)) 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)) 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)) return json_response @staticmethod diff --git a/py-json/realm.py b/py-json/realm.py index c52f79f8f..c22260ae3 100755 --- a/py-json/realm.py +++ b/py-json/realm.py @@ -101,14 +101,20 @@ def __init__(self, _exit_on_error=False, _exit_on_fail=False, _proxy_str=None, - _capture_signal_list=None): + _capture_signal_list=None, + _save_api=False, + _api_log_file_name=None, + _lf_session=None): super().__init__(_lfjson_host=lfclient_host, _lfjson_port=lfclient_port, _debug=debug_, _exit_on_error=_exit_on_error, _exit_on_fail=_exit_on_fail, _proxy_str=_proxy_str, - _capture_signal_list=_capture_signal_list) + _capture_signal_list=_capture_signal_list, + _save_api=_save_api, + _api_log_file_name=_api_log_file_name, + _lf_session=_lf_session) if _capture_signal_list is None: _capture_signal_list = [] diff --git a/py-scripts/lf_webpage.py b/py-scripts/lf_webpage.py index f6acb2c86..0de5fe8a3 100755 --- a/py-scripts/lf_webpage.py +++ b/py-scripts/lf_webpage.py @@ -104,6 +104,7 @@ # from lf_interop_qos import ThroughputQOS import sys import os +import re import importlib import time import argparse @@ -147,6 +148,30 @@ from test_automation import Automation # noqa: E402 +_API_LOG_SESSION_LINE_RE = re.compile(r'^\S+\s+session=(\S+)\s') + + +def _copy_api_log_for_session(src_path, dest_dir, session_id): + """ + Copy api log entries into dest_dir (same basename as src_path). The api log is a + rotating, never-truncated file shared across runs, so if session_id is known, only the + entries tagged with this run's session id are copied -- otherwise (no session was + established) the whole file is copied as-is, which may include other runs' entries too. + """ + dest_path = os.path.join(dest_dir, os.path.basename(src_path)) + if session_id is None: + shutil.copy(src_path, dest_path) + return + with open(src_path) as src, open(dest_path, 'w') as out: + keep_block = False + for line in src: + if line and not line[0].isspace(): + match = _API_LOG_SESSION_LINE_RE.match(line) + keep_block = bool(match) and match.group(1) == session_id + if keep_block: + out.write(line) + + class HttpDownload(Realm): def __init__(self, lfclient_host, lfclient_port, upstream, num_sta, security, ssid, password, ap_name, target_per_ten, file_size, bands, start_id=0, twog_radio=None, fiveg_radio=None, sixg_radio=None, _debug_on=False, _exit_on_error=False, @@ -154,7 +179,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, + _save_api=False, _api_log_file_name=None, _lf_session=None): # super().__init__(lfclient_host=lfclient_host, # lfclient_port=lfclient_port) self.ssid_list = [] @@ -190,7 +216,9 @@ def __init__(self, lfclient_host, lfclient_port, upstream, num_sta, security, ss self.ap_name = ap_name self.windows_ports = [] self.windows_eids = [] - self.local_realm = realm.Realm(lfclient_host=self.host, lfclient_port=self.port) + self.local_realm = realm.Realm(lfclient_host=self.host, lfclient_port=self.port, + _save_api=_save_api, _api_log_file_name=_api_log_file_name, + _lf_session=_lf_session) self.station_profile = self.local_realm.new_station_profile() self.http_profile = self.local_realm.new_http_profile() self.http_profile.requests_per_ten = self.target_per_ten @@ -1515,6 +1543,15 @@ 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 this run's api log entries (json_get/post/put/delete calls) into the report + # folder, if enabled. The source file rotates and isn't truncated per run, so entries + # are filtered down to this run's session id -- see _copy_api_log_for_session(). + if getattr(self.local_realm, 'save_api', False): + try: + _copy_api_log_for_session(self.local_realm.api_log_filename, report_path_date_time, + self.local_realm._session_id()) + except Exception: + logging.info("failed to copy api log file %s to report dir" % self.local_realm.api_log_filename) # It ensures no blocker for virtual clients if self.client_type == 'Real': shutil.move('http_datavalues.csv', report_path_date_time) @@ -2696,6 +2733,10 @@ 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('--save_api', help="save json_get/json_post/json_put/json_delete calls to a lightweight log file", + action="store_true", default=False) + optional.add_argument('--api_log_file_name', help="path to the api log file used when --save_api is set (default: ~/lf_api_calls.log)", + default=None) # ARGS for webGUI required.add_argument('--dowebgui', help="If true will execute script for webgui", default=False) # FOR WEBGUI optional.add_argument('--result_dir', @@ -2881,7 +2922,18 @@ def main(): security = [args.twog_security, args.fiveg_security] ssid = [args.twog_ssid, args.fiveg_ssid] passwd = [args.twog_passwd, args.fiveg_passwd] + lf_session = None + if args.save_api: + # mint a LANforge GUI session id so our lightweight api log can be correlated + # with the GUI's own request logs (same X-LFJson-Session cookie on both) + lanforge_api = importlib.import_module("lanforge_client.lanforge_api") + lf_session = lanforge_api.LFSession(lfclient_url="http://%s:%s" % (args.mgr, args.mgr_port), + debug=False, + require_session=False, + exit_on_error=False) http = HttpDownload(lfclient_host=args.mgr, lfclient_port=args.mgr_port, + _save_api=args.save_api, _api_log_file_name=args.api_log_file_name, + _lf_session=lf_session, upstream=args.upstream_port, num_sta=args.num_stations, security=security, ap_name=args.ap_name, ssid=ssid, password=passwd,