diff --git a/docs/config_reference.rst b/docs/config_reference.rst index f471337fd6..a5277e2147 100644 --- a/docs/config_reference.rst +++ b/docs/config_reference.rst @@ -1362,6 +1362,43 @@ An example configuration of this handler for performance logging is shown here: This handler transmits the whole log record, meaning that all the information will be available and indexable at the remote end. +.. py:attribute:: logging.handlers..httpjson..debug + +.. py:attribute:: logging.handlers_perflog..httpjson..debug + + :required: No + :default: ``false`` + + If set, the ``httpjson`` handler will not attempt to send the data to the server, but it will instead dump the JSON record in the current directory. + The filename has the following form: ``httpjson_record_.json``. + + .. versionadded:: 4.1 + + +.. py:attribute:: logging.handlers..httpjson..json_formatter + +.. py:attribute:: logging.handlers_perflog..httpjson..json_formatter + + A callable for converting the log record into JSON. + + The formatter's signature is the following: + + .. py:function:: json_formatter(record: object, extras: Dict[str, str], ignore_keys: Set[str]) -> str + + :arg record: The prepared log record. + The log record is a simple Python object with all the attributes listed in :attr:`~config.logging.handlers.format`, as well as all the default Python `log record `__ attributes. + In addition to those, there is also the special :attr:`__rfm_check__` attribute that contains a reference to the actual test for which the performance is being logged. + :arg extras: Any extra attributes specified in :attr:`~config.logging.handlers..httpjson..extras`. + :arg ignore_keys: The set of keys specified in :attr:`~config.logging.handlers..httpjson..ignore_keys`. + ReFrame always adds the default Python log record attributes in this set. + :returns: A string representation of the JSON record to be sent to the server or :obj:`None` if the record should not be sent to the server. + + .. note:: + This configuration parameter can only be used in a Python configuration file. + + .. versionadded:: 4.1 + + Execution Mode Configuration ---------------------------- diff --git a/reframe/core/logging.py b/reframe/core/logging.py index 77495eb71d..7c607e34e3 100644 --- a/reframe/core/logging.py +++ b/reframe/core/logging.py @@ -21,6 +21,7 @@ import reframe.utility.osext as osext from reframe.core.exceptions import ConfigError, LoggingError from reframe.core.warnings import suppress_deprecations +from reframe.utility import is_trivially_callable from reframe.utility.profile import TimeProfiler @@ -469,6 +470,11 @@ def _create_graylog_handler(site_config, config_prefix): def _create_httpjson_handler(site_config, config_prefix): url = site_config.get(f'{config_prefix}/url') + extras = site_config.get(f'{config_prefix}/extras') + ignore_keys = site_config.get(f'{config_prefix}/ignore_keys') + json_formatter = site_config.get(f'{config_prefix}/json_formatter') + debug = site_config.get(f'{config_prefix}/debug') + parsed_url = urllib.parse.urlparse(url) if parsed_url.scheme not in {'http', 'https'}: raise ConfigError( @@ -479,27 +485,69 @@ def _create_httpjson_handler(site_config, config_prefix): raise ConfigError('http json handler: invalid hostname') try: - if not parsed_url.port: - raise ConfigError('http json handler: no port given') + port = parsed_url.port + if port is None: + if parsed_url.scheme == 'http': + port = 80 + elif parsed_url.scheme == 'https': + port = 443 + else: + # This should not happen + assert 0, 'invalid url scheme found' except ValueError as e: - raise ConfigError('http json handler: invalid port') from e + raise ConfigError('httpjson handler: invalid port') from e # Check if the remote server is up and accepts connections; if not we will # skip the handler try: - with socket.create_connection((parsed_url.hostname, parsed_url.port), - timeout=1): + with socket.create_connection((parsed_url.hostname, port), timeout=1): pass except OSError as e: getlogger().warning( f'httpjson: could not connect to server ' - f'{parsed_url.hostname}:{parsed_url.port}: {e}' + f'{parsed_url.hostname}:{port}: {e}' ) - return None + if not debug: + return None + + if debug: + getlogger().warning('httpjson: running in debug mode; ' + 'no data will be sent to the server') + + return HTTPJSONHandler(url, extras, ignore_keys, json_formatter, debug) - extras = site_config.get(f'{config_prefix}/extras') - ignore_keys = site_config.get(f'{config_prefix}/ignore_keys') - return HTTPJSONHandler(url, extras, ignore_keys) + +def _record_to_json(record, extras, ignore_keys): + def _can_send(key): + return not key.startswith('_') and not key in ignore_keys + + def _sanitize(s): + return re.sub(r'\W', '_', s) + + json_record = {} + for k, v in record.__dict__.items(): + if not _can_send(k): + continue + + if k == 'check_perfvalues': + # Flatten the performance values + for var, info in v.items(): + val, ref, lower, upper, unit = info + name = _sanitize(var.split(':')[-1]) + json_record[f'check_perf_{name}_value'] = val + json_record[f'check_perf_{name}_ref'] = ref + json_record[f'check_perf_{name}_lower_thres'] = lower + json_record[f'check_perf_{name}_upper_thres'] = upper + json_record[f'check_perf_{name}_unit'] = unit + else: + json_record[k] = v + + if extras: + json_record.update({ + k: v for k, v in extras.items() if _can_send(k) + }) + + return _xfmt(json_record) class HTTPJSONHandler(logging.Handler): @@ -514,35 +562,50 @@ class HTTPJSONHandler(logging.Handler): 'stack_info', 'thread', 'threadName', 'exc_text' } - def __init__(self, url, extras=None, ignore_keys=None): + def __init__(self, url, extras=None, ignore_keys=None, + json_formatter=None, debug=False): super().__init__() self._url = url self._extras = extras - self._ignore_keys = ignore_keys + self._ignore_keys = self.LOG_ATTRS + if ignore_keys: + self._ignore_keys |= set(ignore_keys) - def _record_to_json(self, record): - def _can_send(key): - return not ( - key.startswith('_') or key in HTTPJSONHandler.LOG_ATTRS or - (self._ignore_keys and key in self._ignore_keys) - ) + self._json_format = json_formatter or _record_to_json + if not callable(self._json_format): + raise ConfigError("httpjson: 'json_formatter' is not a callable") - json_record = { - k: v for k, v in record.__dict__.items() if _can_send(k) - } - if self._extras: - json_record.update({ - k: v for k, v in self._extras.items() if _can_send(k) - }) + if not is_trivially_callable(self._json_format, non_def_args=3): + raise ConfigError( + "httpjson: 'json_formatter' has not the right signature: " + "it must be 'json_formatter(record, extras, ignore_keys)'" + ) - return _xfmt(json_record).encode('utf-8') + self._debug = debug def emit(self, record): - json_record = self._record_to_json(record) + # Convert tags to a list to make them JSON friendly + record.check_tags = list(record.check_tags) + json_record = self._json_format(record, + self._extras, + self._ignore_keys) + if json_record is None: + return + + if self._debug: + import time + ts = int(time.time() * 1_000) + dump_file = f'httpjson_record_{ts}.json' + with open(dump_file, 'w') as fp: + fp.write(json_record) + + return + try: requests.post( self._url, data=json_record, - headers={'Content-type': 'application/json'} + headers={'Content-type': 'application/json', + 'Accept-Charset': 'UTF-8'} ) except requests.exceptions.RequestException as e: raise LoggingError('logging failed') from e @@ -899,3 +962,27 @@ def _fn(*args, **kwargs): return fn(*args, **kwargs) return _fn + + +# The following is meant to be used only by the unit tests + +class logging_sandbox: + '''Define a region that you can safely change the logging config. + + At entering the region, this context manager saves the logging + configuration and restores it at exit. + + :meta private: + ''' + + def __enter__(self): + self._logger = _logger + self._perf_logger = _perf_logger + self._context_logger = _context_logger + + def __exit__(self, exc_type, exc_value, traceback): + global _logger, _perf_logger, _context_logger + + _logger = self._logger + _perf_logger = self._perf_logger + _context_logger = self._context_logger diff --git a/reframe/schemas/config.json b/reframe/schemas/config.json index d9108b36bb..e13e084a82 100644 --- a/reframe/schemas/config.json +++ b/reframe/schemas/config.json @@ -163,7 +163,9 @@ "ignore_keys": { "type": "array", "items": {"type": "string"} - } + }, + "json_formatter": {}, + "debug": {"type": "boolean"} }, "required": ["url"] } @@ -565,6 +567,8 @@ "logging/handlers*/graylog_extras": {}, "logging/handlers*/httpjson_extras": {}, "logging/handlers*/httpjson_ignore_keys": [], + "logging/handlers*/httpjson_json_formatter": null, + "logging/handlers*/httpjson_debug": false, "logging/handlers*/stream_name": "stdout", "logging/handlers*/syslog_socktype": "udp", "logging/handlers*/syslog_facility": "user", diff --git a/unittests/test_logging.py b/unittests/test_logging.py index 7aa492ae4c..03bebce50c 100644 --- a/unittests/test_logging.py +++ b/unittests/test_logging.py @@ -251,12 +251,18 @@ def default_exec_ctx(make_exec_ctx_g, config_file): yield from make_exec_ctx_g(config_file()) -def test_valid_level(default_exec_ctx): +@pytest.fixture +def logging_sandbox(): + with rlog.logging_sandbox(): + yield + + +def test_valid_level(default_exec_ctx, logging_sandbox): rlog.configure_logging(rt.runtime().site_config) assert rlog.INFO == rlog.getlogger().getEffectiveLevel() -def test_handler_level(default_exec_ctx, logfile): +def test_handler_level(default_exec_ctx, logfile, logging_sandbox): rlog.configure_logging(rt.runtime().site_config) rlog.getlogger().info('foo') rlog.getlogger().warning('bar') @@ -264,7 +270,7 @@ def test_handler_level(default_exec_ctx, logfile): assert _found_in_logfile('bar', logfile) -def test_handler_append(default_exec_ctx, logfile): +def test_handler_append(default_exec_ctx, logfile, logging_sandbox): rlog.configure_logging(rt.runtime().site_config) rlog.getlogger().warning('foo') _close_handlers() @@ -277,7 +283,8 @@ def test_handler_append(default_exec_ctx, logfile): assert _found_in_logfile('bar', logfile) -def test_handler_noappend(make_exec_ctx, config_file, logfile): +def test_handler_noappend(make_exec_ctx, config_file, + logfile, logging_sandbox): make_exec_ctx( config_file({ 'level': 'info', @@ -307,7 +314,8 @@ def test_handler_noappend(make_exec_ctx, config_file, logfile): assert _found_in_logfile('bar', logfile) -def test_handler_bad_format(make_exec_ctx, config_file, logfile): +def test_handler_bad_format(make_exec_ctx, config_file, + logfile, logging_sandbox): make_exec_ctx( config_file({ 'level': 'info', @@ -330,7 +338,7 @@ def test_handler_bad_format(make_exec_ctx, config_file, logfile): assert _found_in_logfile('