diff --git a/CHANGELOG.rst b/CHANGELOG.rst index 6d39a5f6e0..86cc9f72f0 100644 --- a/CHANGELOG.rst +++ b/CHANGELOG.rst @@ -257,6 +257,50 @@ Fixed Contributed by @Kami. +3.4.1 - March 14, 2021 +---------------------- + +Added +~~~~~ + + +* Service start up code has been updated to log a warning if a non-utf-8 encoding / locale is + detected. + + Using non-utf-8 locale while working with unicode data will result in various issues so users + are strongly recommended to ensure encoding for all the StackStorm service is + set to ``utf-8``. (#5182) + + Contributed by @Kami. + +Changed +~~~~~~~ + +* Use `sudo -E` to fix GitHub Actions tests #5187 + + Contributed by @cognifloyd + +Fixed +~~~~~ + +* Properly handle unicode strings in logs #5184 + + Fix a logging loop when attempting to encode Unicode characters in locales that do not support + Unicode characters - CVE-2021-28667. + + See https://stackstorm.com/2021/03/10/stackstorm-v3-4-1-security-fix/ for more information. + + Contributed by @Kami + +* Fix SensorTypeAPI schema to use class_name instead of name since documentation for pack + development uses class_name and registrar used to load sensor to database assign class_name + to name in the database model. (bug fix) + +* Updated paramiko version to 2.7.2, to go with updated cryptography to prevent problems + with ssh keys on remote actions. #5201 + + Contributed by Amanda McGuinness (@amanda11 Ammeon Solutions) + 3.4.0 - March 02, 2021 ---------------------- diff --git a/st2common/st2common/log.py b/st2common/st2common/log.py index 42e99a3169..d55a165049 100644 --- a/st2common/st2common/log.py +++ b/st2common/st2common/log.py @@ -61,10 +61,24 @@ "audit", ] +# True if sys.stdout should be patched and re-opened with utf-8 encoding in situations where +# utf-8 encoding is not used (if we don't do that and a logger tries to log a unicode string, +# log format would go in an infinite loop). +# We only expose this variable for testing purposes +PATCH_STDOUT = os.environ.get("ST2_LOG_PATCH_STDOUT", "true").lower() in [ + "true", + "1", + "yes", +] + +LOG = logging.getLogger(__name__) + # Note: This attribute is used by "find_caller" so it can correctly exclude this file when looking # for the logger method caller frame. _srcfile = get_normalized_file_path(__file__) +_original_stdstderr = sys.stderr + def find_caller(stack_info=False, stacklevel=1): """ @@ -193,6 +207,13 @@ def __init__(self, name, level=logging.ERROR): self._level = level def write(self, message): + # Work around for infinite loop issue - ensure we don't log unicode data. + # If message contains unicode sequences and process locale is not set to utf-8, it would + # result in infinite lop in _log on formatting the message. + # This is because of the differences between Python 2.7 and Python 3 with log error + # handlers. + message = message.encode("utf-8", "replace").decode("ascii", "ignore") + self._logger._log(self._level, message, None) def flush(self): @@ -218,6 +239,33 @@ def _redirect_stderr(): sys.stderr = LoggingStream("STDERR") +def _patch_stdout(): + """ + This function re-opens sys.stdout using utf-8 encoding. + + It's to be used in situations where process encoding / locale is not set to utf-8. In such + situations when unicode sequence is logged, it would cause logging formatter to go in an infite + loop on formatting a record. + + This function works around that by ensuring sys.stdout is always opened in utf-8 mode. + """ + + stdout_encoding = str(getattr(sys.stdout, "encoding", "none")).lower() + + if stdout_encoding not in ["utf8", "utf-8"] and PATCH_STDOUT: + LOG.info( + "Patching sys.stdout and re-opening it with utf-8 encoding (originally opened " + "with %s encoding)..." % (stdout_encoding) + ) + sys.stdout = open( + sys.stdout.fileno(), + mode="w", + encoding="utf-8", + errors="replace", + buffering=1, + ) + + def setup( config_file, redirect_stderr=True, @@ -249,6 +297,7 @@ def setup( _add_exclusion_filters(handlers=handlers, excludes=excludes) if redirect_stderr: _redirect_stderr() + _patch_stdout() except Exception as exc: exc_cls = type(exc) tb_msg = traceback.format_exc() diff --git a/st2common/st2common/service_setup.py b/st2common/st2common/service_setup.py index 065ce98833..cb3e1433f9 100644 --- a/st2common/st2common/service_setup.py +++ b/st2common/st2common/service_setup.py @@ -62,6 +62,19 @@ "register_service_in_service_registry", ] +# Message which is logged if non utf-8 locale is detected on startup. +NON_UTF8_LOCALE_WARNING_MSG = """ +Detected a non utf-8 locale / encoding (fs encoding: %s, default encoding: %s, locale: %s). +Using non utf-8 locale while working with unicode data will result in exceptions and undefined +behavior. +You are strongly encouraged to configure all the StackStorm services to use utf-8 encoding (e.g. +LANG=en_US.UTF-8). +""".strip().replace( + "\n", " " +) + +VALID_UTF8_ENCODINGS = ["utf8", "utf-8"] + LOG = logging.getLogger(__name__) @@ -121,7 +134,8 @@ def setup( fs_encoding = sys.getfilesystemencoding() default_encoding = sys.getdefaultencoding() lang_env = os.environ.get("LANG", "unknown") - + lang_env = os.environ.get("LANG", "notset") + pythonioencoding_env = os.environ.get("PYTHONIOENCODING", "notset") try: language_code, encoding = locale.getdefaultlocale() @@ -134,8 +148,9 @@ def setup( LOG.info("Using Python: %s (%s)" % (version, sys.executable)) LOG.info( - "Using fs encoding: %s, default encoding: %s, LANG env variable: %s, locale: %s" - % (fs_encoding, default_encoding, lang_env, used_locale) + "Using fs encoding: %s, default encoding: %s, locale: %s, LANG env variable: %s, " + "PYTHONIOENCODING env variable: %s" + % (fs_encoding, default_encoding, lang_env, used_locale, pythonioencoding_env) ) config_file_paths = cfg.CONF.config_file @@ -147,10 +162,20 @@ def setup( logging_config_path = os.path.abspath(logging_config_path) LOG.info("Using logging config: %s", logging_config_path) - LOG.info("Using coordination driver: %s", get_driver_name()) LOG.info("Using metrics driver: %s", cfg.CONF.metrics.driver) + # Warn on non utf-8 locale which could cause issues when running under Python 3 and working + # with unicode data + if ( + fs_encoding.lower() not in VALID_UTF8_ENCODINGS + or encoding.lower() not in VALID_UTF8_ENCODINGS + ): + LOG.warning( + NON_UTF8_LOCALE_WARNING_MSG + % (fs_encoding, default_encoding, used_locale.strip()) + ) + is_debug_enabled = cfg.CONF.debug or cfg.CONF.system.debug try: @@ -183,8 +208,15 @@ def setup( and handler.level < stdlib_logging.AUDIT ) if not is_debug_enabled and ignore_audit_log_messages: + try: + handler_repr = str(handler) + except TypeError: + # In case handler doesn't have name assigned, repr would throw + handler_repr = "unknown" + LOG.debug( - 'Excluding log messages with level "AUDIT" for handler "%s"' % (handler) + 'Excluding log messages with level "AUDIT" for handler "%s"' + % (handler_repr) ) handler.addFilter(LogLevelFilter(log_levels=exclude_log_levels)) diff --git a/st2common/tests/integration/log_unicode_data.py b/st2common/tests/integration/log_unicode_data.py new file mode 100644 index 0000000000..a4a30f664f --- /dev/null +++ b/st2common/tests/integration/log_unicode_data.py @@ -0,0 +1,86 @@ +# -*- coding: utf-8 -*- +# Copyright 2020 The StackStorm Authors. +# Copyright 2019 Extreme Networks, Inc. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +""" +This file is used to test edge case with logging unicode data. +""" + +from __future__ import absolute_import + +import os +import sys + +from oslo_config import cfg + +BASE_DIR = os.path.dirname(os.path.abspath(__file__)) + +ST2ACTIONS_PATH = os.path.join(BASE_DIR, "../../../st2actions") +ST2COMMON_PATH = os.path.join(BASE_DIR, "../../") +ST2TESTS_PATH = os.path.join(BASE_DIR, "../../../st2tests") + +# Ensure st2actions is in PYTHONPATH. +# This is needed since this script is spawned from inside integration tests +sys.path.append(ST2ACTIONS_PATH) +sys.path.append(ST2COMMON_PATH) +sys.path.append(ST2TESTS_PATH) + +from st2actions.notifier import config +from st2common import log as logging +from st2common.service_setup import setup as common_setup + +FIXTURES_DIR = os.path.join(ST2TESTS_PATH, "st2tests/fixtures") +ST2_CONFIG_DEBUG_LL_PATH = os.path.join( + FIXTURES_DIR, "conf/st2.tests.api.debug_log_level.conf" +) + +LOG = logging.getLogger(__name__) + + +def main(): + cfg.CONF.set_override("debug", True) + common_setup( + service="test", + config=config, + setup_db=False, + run_migrations=False, + register_runners=False, + register_internal_trigger_types=False, + register_mq_exchanges=False, + register_signal_handlers=False, + service_registry=False, + config_args=["--config-file", ST2_CONFIG_DEBUG_LL_PATH], + ) + + LOG.info("Test info message 1") + LOG.debug("Test debug message 1") + + # 1. Actual unicode sequence + LOG.info("Test info message with unicode 1 - 好好好") + LOG.debug("Test debug message with unicode 1 - 好好好") + + # 2. Ascii escape sequence + LOG.info( + "Test info message with unicode 1 - " + + "好好好".encode("ascii", "backslashreplace").decode("ascii", "backslashreplace") + ) + LOG.debug( + "Test debug message with unicode 1 - " + + "好好好".encode("ascii", "backslashreplace").decode("ascii", "backslashreplace") + ) + + +if __name__ == "__main__": + main() diff --git a/st2common/tests/integration/test_logging.py b/st2common/tests/integration/test_logging.py new file mode 100644 index 0000000000..af4eab3bf1 --- /dev/null +++ b/st2common/tests/integration/test_logging.py @@ -0,0 +1,259 @@ +# Copyright 2020 The StackStorm Authors. +# Copyright 2019 Extreme Networks, Inc. +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from __future__ import absolute_import + +import os +import sys +import signal + +import eventlet +from eventlet.green import subprocess + +from st2tests.base import IntegrationTestCase + +BASE_DIR = os.path.dirname(os.path.abspath(__file__)) + +TEST_FILE_PATH = os.path.join(BASE_DIR, "log_unicode_data.py") + + +class LogFormattingAndEncodingTestCase(IntegrationTestCase): + def test_formatting_with_unicode_data_works_no_stdout_patching(self): + # Ensure that process doesn't end up in an infinite loop if non-utf8 locale / encoding is + # used and a unicode sequence is logged. + + # 1. Process is using a utf-8 encoding + process = self._start_process( + env={ + "LC_ALL": "en_US.UTF-8", + "ST2_LOG_PATCH_STDOUT": "false", + "PYTHONIOENCODING": "utf-8", + } + ) + self.add_process(process=process) + + # Give it some time to start up and run for a while + eventlet.sleep(2) + process.send_signal(signal.SIGKILL) + + stdout = process.stdout.read().decode("utf-8").strip() + stderr = process.stderr.read().decode("utf-8").strip() + stdout_lines = stdout.split("\n") + + self.assertEqual(stderr, "") + self.assertTrue(len(stdout_lines) < 20) + + self.assertIn("INFO [-] Test info message 1", stdout) + self.assertIn("Test debug message 1", stdout) + self.assertIn("INFO [-] Test info message with unicode 1 - 好好好", stdout) + self.assertIn("DEBUG [-] Test debug message with unicode 1 - 好好好", stdout) + self.assertIn( + "INFO [-] Test info message with unicode 1 - \u597d\u597d\u597d", stdout + ) + self.assertIn( + "DEBUG [-] Test debug message with unicode 1 - \u597d\u597d\u597d", stdout + ) + + # 2. Process is not using utf-8 encoding - LC_ALL set to invalid locale - should result in + # single exception being logged, but not infinite loop + process = self._start_process( + env={ + "LC_ALL": "invalid", + "ST2_LOG_PATCH_STDOUT": "false", + "PYTHONIOENCODING": "utf-8", + } + ) + self.add_process(process=process) + + # Give it some time to start up and run for a while + eventlet.sleep(2) + process.send_signal(signal.SIGKILL) + + stdout = process.stdout.read().decode("utf-8") + stderr = process.stderr.read().decode("utf-8") + stdout_lines = stdout.split("\n") + + self.assertEqual(stderr, "") + + self.assertIn("ERROR [-] ", stdout) + self.assertIn("can't encode", stdout) + self.assertIn("'ascii' codec can't encode", stdout) + + self.assertTrue(len(stdout_lines) >= 50) + self.assertTrue(len(stdout_lines) < 100) + + self.assertIn("INFO [-] Test info message 1", stdout) + self.assertIn("Test debug message 1", stdout) + self.assertIn("INFO [-] Test info message with unicode 1 - 好好好", stdout) + self.assertIn("DEBUG [-] Test debug message with unicode 1 - 好好好", stdout) + self.assertIn( + "INFO [-] Test info message with unicode 1 - \u597d\u597d\u597d", stdout + ) + self.assertIn( + "DEBUG [-] Test debug message with unicode 1 - \u597d\u597d\u597d", stdout + ) + + # 3. Process is not using utf-8 encoding - PYTHONIOENCODING set to ascii - should result in + # single exception being logged, but not infinite loop + process = self._start_process( + env={ + "LC_ALL": "en_US.UTF-8", + "ST2_LOG_PATCH_STDOUT": "false", + "PYTHONIOENCODING": "ascii", + } + ) + self.add_process(process=process) + + # Give it some time to start up and run for a while + eventlet.sleep(2) + process.send_signal(signal.SIGKILL) + + stdout = process.stdout.read().decode("utf-8") + stderr = process.stderr.read().decode("utf-8") + stdout_lines = stdout.split("\n") + + self.assertEqual(stderr, "") + + self.assertIn("ERROR [-] ", stdout) + self.assertIn("can't encode", stdout) + self.assertIn("'ascii' codec can't encode", stdout) + + self.assertTrue(len(stdout_lines) >= 50) + self.assertTrue(len(stdout_lines) < 100) + + self.assertIn("INFO [-] Test info message 1", stdout) + self.assertIn("Test debug message 1", stdout) + self.assertNotIn("INFO [-] Test info message with unicode 1 - 好好好", stdout) + self.assertNotIn("DEBUG [-] Test debug message with unicode 1 - 好好好", stdout) + self.assertNotIn( + "INFO [-] Test info message with unicode 1 - \u597d\u597d\u597d", stdout + ) + self.assertNotIn( + "DEBUG [-] Test debug message with unicode 1 - \u597d\u597d\u597d", stdout + ) + + def test_formatting_with_unicode_data_works_with_stdout_patching(self): + # Test a scenario where patching is enabled which means it should never result in infinite + # loop + # 1. Process is using a utf-8 encoding + process = self._start_process( + env={ + "LC_ALL": "en_US.UTF-8", + "ST2_LOG_PATCH_STDOUT": "true", + "PYTHONIOENCODING": "utf-8", + } + ) + self.add_process(process=process) + + # Give it some time to start up and run for a while + eventlet.sleep(2) + process.send_signal(signal.SIGKILL) + + stdout = process.stdout.read().decode("utf-8") + stderr = process.stderr.read().decode("utf-8") + stdout_lines = stdout.split("\n") + print(stderr) + + self.assertEqual(stderr, "") + self.assertTrue(len(stdout_lines) < 20) + + self.assertIn("INFO [-] Test info message 1", stdout) + self.assertIn("Test debug message 1", stdout) + self.assertIn("INFO [-] Test info message with unicode 1 - 好好好", stdout) + self.assertIn("DEBUG [-] Test debug message with unicode 1 - 好好好", stdout) + self.assertIn( + "INFO [-] Test info message with unicode 1 - \u597d\u597d\u597d", stdout + ) + self.assertIn( + "DEBUG [-] Test debug message with unicode 1 - \u597d\u597d\u597d", stdout + ) + + # 2. Process is not using utf-8 encoding + process = self._start_process( + env={ + "LC_ALL": "invalid", + "ST2_LOG_PATCH_STDOUT": "true", + "PYTHONIOENCODING": "utf-8", + } + ) + self.add_process(process=process) + + # Give it some time to start up and run for a while + eventlet.sleep(2) + process.send_signal(signal.SIGKILL) + + stdout = process.stdout.read().decode("utf-8") + stderr = process.stderr.read().decode("utf-8") + + self.assertEqual(stderr, "") + self.assertTrue(len(stdout_lines) < 50) + + self.assertIn("INFO [-] Test info message 1", stdout) + self.assertIn("Test debug message 1", stdout) + self.assertIn("INFO [-] Test info message with unicode 1 - 好好好", stdout) + self.assertIn("DEBUG [-] Test debug message with unicode 1 - 好好好", stdout) + self.assertIn( + "INFO [-] Test info message with unicode 1 - \u597d\u597d\u597d", stdout + ) + self.assertIn( + "DEBUG [-] Test debug message with unicode 1 - \u597d\u597d\u597d", stdout + ) + + # 3. Process is not using utf-8 encoding - PYTHONIOENCODING set to ascii + process = self._start_process( + env={ + "LC_ALL": "en_US.UTF-8", + "ST2_LOG_PATCH_STDOUT": "true", + "PYTHONIOENCODING": "ascii", + } + ) + self.add_process(process=process) + + # Give it some time to start up and run for a while + eventlet.sleep(2) + process.send_signal(signal.SIGKILL) + + stdout = process.stdout.read().decode("utf-8") + stderr = process.stderr.read().decode("utf-8") + stdout_lines = stdout.split("\n") + + self.assertEqual(stderr, "") + + self.assertTrue(len(stdout_lines) < 20) + + self.assertIn("Patching sys.stdout", stdout) + self.assertIn("INFO [-] Test info message 1", stdout) + self.assertIn("Test debug message 1", stdout) + self.assertIn("INFO [-] Test info message with unicode 1 - 好好好", stdout) + self.assertIn("DEBUG [-] Test debug message with unicode 1 - 好好好", stdout) + self.assertIn( + "INFO [-] Test info message with unicode 1 - \u597d\u597d\u597d", stdout + ) + self.assertIn( + "DEBUG [-] Test debug message with unicode 1 - \u597d\u597d\u597d", stdout + ) + + def _start_process(self, env=None): + cmd = [sys.executable, TEST_FILE_PATH] + process = subprocess.Popen( + cmd, + env=env or os.environ.copy(), + cwd=os.getcwd(), + stdout=subprocess.PIPE, + stderr=subprocess.PIPE, + shell=False, + preexec_fn=os.setsid, + ) + return process diff --git a/st2common/tests/integration/test_service_setup_log_level_filtering.py b/st2common/tests/integration/test_service_setup_log_level_filtering.py index 9062319808..40313d93ee 100644 --- a/st2common/tests/integration/test_service_setup_log_level_filtering.py +++ b/st2common/tests/integration/test_service_setup_log_level_filtering.py @@ -64,6 +64,38 @@ class ServiceSetupLogLevelFilteringTestCase(IntegrationTestCase): + def test_system_info_is_logged_on_startup(self): + # Verify INFO level service start up messages + process = self._start_process(config_path=ST2_CONFIG_INFO_LL_PATH) + self.add_process(process=process) + + # Give it some time to start up + eventlet.sleep(3) + process.send_signal(signal.SIGKILL) + + # Verify first 4 environment related log messages + stdout = process.stdout.read().decode("utf-8") + self.assertIn("INFO [-] Using Python:", stdout) + self.assertIn("INFO [-] Using fs encoding:", stdout) + self.assertIn("INFO [-] Using config files:", stdout) + self.assertIn("INFO [-] Using logging config:", stdout) + + def test_warning_is_emitted_on_non_utf8_encoding(self): + env = os.environ.copy() + env["LC_ALL"] = "invalid" + process = self._start_process(config_path=ST2_CONFIG_INFO_LL_PATH, env=env) + self.add_process(process=process) + + # Give it some time to start up + eventlet.sleep(3) + process.send_signal(signal.SIGKILL) + + # Verify first 4 environment related log messages + stdout = "\n".join(process.stdout.read().decode("utf-8").split("\n")) + self.assertIn("WARNING [-] Detected a non utf-8 locale / encoding", stdout) + self.assertIn("fs encoding: ascii", stdout) + self.assertIn("unknown locale: invalid", stdout) + def test_audit_log_level_is_filtered_if_log_level_is_not_debug_or_audit(self): # 0. Verify INFO level service start up messages process = self._start_process(config_path=ST2_CONFIG_INFO_LL_PATH) @@ -165,12 +197,13 @@ def test_kombu_heartbeat_tick_log_messages_are_excluded(self): stdout = "\n".join(process.stdout.read().decode("utf-8").split("\n")) self.assertNotIn("heartbeat_tick", stdout) - def _start_process(self, config_path): + def _start_process(self, config_path, env=None): cmd = CMD + [config_path] cwd = os.path.abspath(os.path.join(BASE_DIR, "../../../")) cwd = os.path.abspath(cwd) process = subprocess.Popen( cmd, + env=env or os.environ.copy(), cwd=cwd, stdout=subprocess.PIPE, stderr=subprocess.PIPE,