diff --git a/openc3/lib/openc3/utilities/env_helper.rb b/openc3/lib/openc3/utilities/env_helper.rb new file mode 100644 index 0000000000..31b416ef44 --- /dev/null +++ b/openc3/lib/openc3/utilities/env_helper.rb @@ -0,0 +1,10 @@ +# For simple boolean flags +class EnvHelper + def self.enabled?(key) + ['true', '1', 'yes', 'on'].include?(ENV[key].to_s.downcase) + end + + def self.set?(key) + !ENV[key].to_s.empty? + end +end diff --git a/openc3/lib/openc3/utilities/logger.rb b/openc3/lib/openc3/utilities/logger.rb index 15e42c00f1..f40fc9883f 100644 --- a/openc3/lib/openc3/utilities/logger.rb +++ b/openc3/lib/openc3/utilities/logger.rb @@ -20,6 +20,7 @@ # This file may also be used under the terms of a commercial license # if purchased from OpenC3, Inc. +require 'openc3' require 'openc3/core_ext/class' require 'openc3/core_ext/time' require 'openc3/utilities/store_queued' @@ -27,6 +28,7 @@ require 'logger' require 'time' require 'json' +require 'openc3/utilities/env_helper' module OpenC3 # Supports different levels of logging and only writes if the level @@ -201,19 +203,14 @@ def log_message(log_level, message, scope:, user:, type:, url:, other: nil, &blo @@mutex.synchronize do data = build_log_data(log_level, message, user: user, type: type, url: url, other: other, &block) if @stdout - case log_level - when WARN_LEVEL, ERROR_LEVEL, FATAL_LEVEL - if ENV['OPENC3_LOG_STDERR'] - $stderr.puts data.as_json().to_json(allow_nan: true) - $stderr.flush - else - $stdout.puts data.as_json().to_json(allow_nan: true) - $stdout.flush - end + # send warning, error, and fatal to stderr if OPENC3_LOG_STDERR env var is set to 1 or true + if [WARN_LEVEL, ERROR_LEVEL, FATAL_LEVEL].include?(log_level) && EnvHelper.enabled?('OPENC3_LOG_STDERR') + io = $stderr else - $stdout.puts data.as_json().to_json(allow_nan: true) - $stdout.flush + io = $stdout end + io.puts data.as_json().to_json(allow_nan: true) + io.flush end unless @no_store if scope diff --git a/openc3/python/openc3/environment.py b/openc3/python/openc3/environment.py index aab1faab2b..c49634e3ee 100644 --- a/openc3/python/openc3/environment.py +++ b/openc3/python/openc3/environment.py @@ -61,6 +61,45 @@ _openc3_keycloak_url = "OPENC3_KEYCLOAK_URL" _openc3_redis_cluster = "OPENC3_REDIS_CLUSTER" +def get_env_bool(key: str, default: bool = False) -> bool: + """ + Helper function to read boolean values from environment variables. + + Treats the following values (case-insensitive) as True: + - 'true' + - '1' + - 'yes' + - 'on' + + All other values (including empty string, 'false', '0', etc.) are treated as False. + If the environment variable is not set, returns the default value. + + Args: + key: The environment variable name to read + default: The default value to return if the environment variable is not set + + Returns: + bool: True if the environment variable is set to a truthy value, False otherwise + + Examples: + >>> os.environ['DEBUG'] = 'true' + >>> get_env_bool('DEBUG') + True + >>> get_env_bool('MISSING_VAR', default=True) + True + >>> os.environ['FLAG'] = '1' + >>> get_env_bool('FLAG') + True + >>> os.environ['FLAG'] = 'false' + >>> get_env_bool('FLAG') + False + """ + value = os.environ.get(key) + if value is None: + return default + return value.lower() in ('true', '1', 'yes', 'on') + + OPENC3_API_SCHEMA = os.environ.get(_openc3_api_schema, "http") OPENC3_API_HOSTNAME = os.environ.get(_openc3_api_hostname, "openc3-cosmos-cmd-tlm-api") try: @@ -109,7 +148,7 @@ OPENC3_LOCAL_MODE = os.environ.get(_openc3_local_mode) OPENC3_LOCAL_MODE_PATH = os.environ.get(_openc3_local_mode_path) OPENC3_NO_BUCKET_POLICY = os.environ.get(_openc3_no_bucket_policy) -OPENC3_LOG_STDERR = os.environ.get(_openc3_log_stderr) +OPENC3_LOG_STDERR = get_env_bool(_openc3_log_stderr) OPENC3_SCOPE = os.environ.get(_openc3_scope, "DEFAULT") OPENC3_API_PASSWORD = os.environ.get(_openc3_api_password) diff --git a/openc3/python/openc3/utilities/logger.py b/openc3/python/openc3/utilities/logger.py index 45bb14f5e0..06fae9ca59 100644 --- a/openc3/python/openc3/utilities/logger.py +++ b/openc3/python/openc3/utilities/logger.py @@ -202,7 +202,7 @@ def fatal(self, message=None, scope=None, user=None, type=LOG, url=None, other=N other=other, ) - def build_log_data(self, log_level, message, user=None, type=None, url=None, other=None): + def build_log_data(self, log_level: str, message: str | None, user=None, type=None, url=None, other=None): now_time = datetime.now(timezone.utc) data = { "time": int(now_time.timestamp() * 1000000000), @@ -228,21 +228,16 @@ def build_log_data(self, log_level, message, user=None, type=None, url=None, oth data = data | other return data - def log_message(self, log_level, message, scope, user, type, url, other=None): + def log_message(self, log_level: str, message: str | None, scope, user, type, url, other=None): with self.instance_mutex: data = self.build_log_data(log_level, message, user, type, url, other) if self.stdout: - match log_level: - case "WARN" | "ERROR" | "FATAL": - if OPENC3_LOG_STDERR: - print(json.dumps(data), file=sys.stderr) - sys.stderr.flush() - else: - print(json.dumps(data), file=sys.stdout) - sys.stdout.flush() - case _: - print(json.dumps(data), file=sys.stdout) - sys.stdout.flush() + if (log_level in ['WARN', 'ERROR', 'FATAL']) and OPENC3_LOG_STDERR: + io = sys.stderr + else: + io = sys.stdout + print(json.dumps(data), file=io) + io.flush() if self.no_store is False: if scope is not None: EphemeralStoreQueued.write_topic(f"{scope}__openc3_log_messages", data) diff --git a/openc3/python/test/utilities/test_logger.py b/openc3/python/test/utilities/test_logger.py index f742c07521..083d920957 100644 --- a/openc3/python/test/utilities/test_logger.py +++ b/openc3/python/test/utilities/test_logger.py @@ -14,6 +14,7 @@ # This file may also be used under the terms of a commercial license # if purchased from OpenC3, Inc. +import os import time import json import unittest @@ -92,3 +93,495 @@ def test_fatal_only_prints_if_level_is_fatal(self): def test_help(self): help(Logger) # NOSONAR + + +class TestLogMessage(unittest.TestCase): + def setUp(self): + Logger.stdout = True + Logger.level = Logger.INFO + Logger.no_store = True + Logger.microservice_name = None + Logger.detail_string = None + + def tearDown(self): + sys.stdout = sys.__stdout__ + sys.stderr = sys.__stderr__ + + def test_log_message_includes_required_fields(self): + """Test that log_message includes all required fields in output""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.log_message("INFO", "Test message", scope="TEST", user=None, type=Logger.LOG, url=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertEqual(data["level"], "INFO") + self.assertEqual(data["message"], "Test message") + self.assertIn("time", data) + self.assertIn("@timestamp", data) + self.assertIn("container_name", data) + + def test_log_message_with_microservice_name(self): + """Test that microservice_name is included when set""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.microservice_name = "test-service" + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertEqual(data["microservice_name"], "test-service") + + def test_log_message_without_microservice_name(self): + """Test that microservice_name is omitted when None""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.microservice_name = None + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertNotIn("microservice_name", data) + + def test_log_message_with_detail_string(self): + """Test that detail is included when detail_string is set""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.detail_string = "Additional details" + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertEqual(data["detail"], "Additional details") + + def test_log_message_without_detail_string(self): + """Test that detail is omitted when detail_string is None""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.detail_string = None + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertNotIn("detail", data) + + def test_log_message_with_user(self): + """Test that user is included when provided""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.log_message("INFO", "Test", scope="TEST", user="testuser", type=Logger.LOG, url=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertEqual(data["user"], "testuser") + + def test_log_message_without_user(self): + """Test that user is omitted when None""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertNotIn("user", data) + + def test_log_message_with_type(self): + """Test that type is included when provided""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.log_message("INFO", "Test", scope="TEST", user=None, type="notification", url=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertEqual(data["type"], "notification") + + def test_log_message_without_type(self): + """Test that type is omitted when None""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.log_message("INFO", "Test", scope="TEST", user=None, type=None, url=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertNotIn("type", data) + + def test_log_message_with_url(self): + """Test that url is included when provided""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url="http://example.com") + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertEqual(data["url"], "http://example.com") + + def test_log_message_without_url(self): + """Test that url is omitted when None""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertNotIn("url", data) + + def test_log_message_with_other_dict(self): + """Test that other dict merges additional fields""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + other = {"request_id": "12345", "custom_field": "custom_value"} + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url=None, other=other) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertEqual(data["request_id"], "12345") + self.assertEqual(data["custom_field"], "custom_value") + + def test_log_message_with_nested_other_dict(self): + """Test that nested structures in other dict are preserved""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + other = { + "metadata": { + "source": "test", + "version": "1.0" + }, + "tags": ["error", "critical"] + } + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url=None, other=other) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertEqual(data["metadata"]["source"], "test") + self.assertEqual(data["metadata"]["version"], "1.0") + self.assertEqual(data["tags"], ["error", "critical"]) + + def test_log_message_without_other(self): + """Test that other is handled when None""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url=None, other=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + # Should only have standard fields + self.assertIn("level", data) + self.assertIn("message", data) + + def test_log_message_with_none_message(self): + """Test that message can be None""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.log_message("INFO", None, scope="TEST", user=None, type=Logger.LOG, url=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + self.assertNotIn("message", data) + + @patch.dict(os.environ, {"OPENC3_LOG_STDERR": ""}, clear=False) + def test_log_message_stdout_when_stderr_not_enabled(self): + """Test that all log levels go to stdout when OPENC3_LOG_STDERR is not enabled""" + from openc3.environment import OPENC3_LOG_STDERR + # Force reload to pick up the environment variable + import importlib + import openc3.environment + importlib.reload(openc3.environment) + + orig_stdout = sys.stdout + orig_stderr = sys.stderr + sys.stdout = StringIO() + sys.stderr = StringIO() + + logger = Logger() + logger.log_message("WARN", "Warning", scope="TEST", user=None, type=Logger.LOG, url=None) + logger.log_message("ERROR", "Error", scope="TEST", user=None, type=Logger.LOG, url=None) + logger.log_message("FATAL", "Fatal", scope="TEST", user=None, type=Logger.LOG, url=None) + + stdout_output = sys.stdout.getvalue() + stderr_output = sys.stderr.getvalue() + + sys.stdout = orig_stdout + sys.stderr = orig_stderr + + # All should go to stdout + self.assertIn("Warning", stdout_output) + self.assertIn("Error", stdout_output) + self.assertIn("Fatal", stdout_output) + self.assertEqual(stderr_output, "") + + @patch('openc3.utilities.logger.OPENC3_LOG_STDERR', True) + def test_log_message_stderr_when_enabled_for_warn(self): + """Test that WARN goes to stderr when OPENC3_LOG_STDERR is enabled""" + orig_stdout = sys.stdout + orig_stderr = sys.stderr + sys.stdout = StringIO() + sys.stderr = StringIO() + + logger = Logger() + logger.log_message("WARN", "Warning", scope="TEST", user=None, type=Logger.LOG, url=None) + + stdout_output = sys.stdout.getvalue() + stderr_output = sys.stderr.getvalue() + + sys.stdout = orig_stdout + sys.stderr = orig_stderr + + self.assertEqual(stdout_output, "") + self.assertIn("Warning", stderr_output) + data = json.loads(stderr_output) + self.assertEqual(data["level"], "WARN") + + @patch('openc3.utilities.logger.OPENC3_LOG_STDERR', True) + def test_log_message_stderr_when_enabled_for_error(self): + """Test that ERROR goes to stderr when OPENC3_LOG_STDERR is enabled""" + orig_stdout = sys.stdout + orig_stderr = sys.stderr + sys.stdout = StringIO() + sys.stderr = StringIO() + + logger = Logger() + logger.log_message("ERROR", "Error message", scope="TEST", user=None, type=Logger.LOG, url=None) + + stdout_output = sys.stdout.getvalue() + stderr_output = sys.stderr.getvalue() + + sys.stdout = orig_stdout + sys.stderr = orig_stderr + + self.assertEqual(stdout_output, "") + self.assertIn("Error message", stderr_output) + + @patch('openc3.utilities.logger.OPENC3_LOG_STDERR', True) + def test_log_message_stderr_when_enabled_for_fatal(self): + """Test that FATAL goes to stderr when OPENC3_LOG_STDERR is enabled""" + orig_stdout = sys.stdout + orig_stderr = sys.stderr + sys.stdout = StringIO() + sys.stderr = StringIO() + + logger = Logger() + logger.log_message("FATAL", "Fatal error", scope="TEST", user=None, type=Logger.LOG, url=None) + + stdout_output = sys.stdout.getvalue() + stderr_output = sys.stderr.getvalue() + + sys.stdout = orig_stdout + sys.stderr = orig_stderr + + self.assertEqual(stdout_output, "") + self.assertIn("Fatal error", stderr_output) + + @patch('openc3.utilities.logger.OPENC3_LOG_STDERR', True) + def test_log_message_stdout_for_info_when_stderr_enabled(self): + """Test that INFO still goes to stdout when OPENC3_LOG_STDERR is enabled""" + orig_stdout = sys.stdout + orig_stderr = sys.stderr + sys.stdout = StringIO() + sys.stderr = StringIO() + + logger = Logger() + logger.log_message("INFO", "Info message", scope="TEST", user=None, type=Logger.LOG, url=None) + + stdout_output = sys.stdout.getvalue() + stderr_output = sys.stderr.getvalue() + + sys.stdout = orig_stdout + sys.stderr = orig_stderr + + self.assertIn("Info message", stdout_output) + self.assertEqual(stderr_output, "") + + @patch('openc3.utilities.logger.OPENC3_LOG_STDERR', True) + def test_log_message_stdout_for_debug_when_stderr_enabled(self): + """Test that DEBUG goes to stdout when OPENC3_LOG_STDERR is enabled""" + orig_stdout = sys.stdout + orig_stderr = sys.stderr + sys.stdout = StringIO() + sys.stderr = StringIO() + + logger = Logger() + logger.log_message("DEBUG", "Debug message", scope="TEST", user=None, type=Logger.LOG, url=None) + + stdout_output = sys.stdout.getvalue() + stderr_output = sys.stderr.getvalue() + + sys.stdout = orig_stdout + sys.stderr = orig_stderr + + self.assertIn("Debug message", stdout_output) + self.assertEqual(stderr_output, "") + + def test_log_message_respects_stdout_false(self): + """Test that no output when stdout is False""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.stdout = False + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + self.assertEqual(output, "") + + @patch("openc3.utilities.logger.EphemeralStoreQueued") + def test_log_message_writes_to_store_with_scope(self, mock_store): + """Test that log messages are written to store with scope""" + logger = Logger() + logger.no_store = False + logger.log_message("INFO", "Test", scope="TESTSCOPE", user=None, type=Logger.LOG, url=None) + + mock_store.write_topic.assert_called_once() + call_args = mock_store.write_topic.call_args + self.assertEqual(call_args[0][0], "TESTSCOPE__openc3_log_messages") + self.assertIsInstance(call_args[0][1], dict) + self.assertEqual(call_args[0][1]["message"], "Test") + + @patch("openc3.utilities.logger.EphemeralStoreQueued") + def test_log_message_writes_to_store_without_scope(self, mock_store): + """Test that log messages are written to NOSCOPE when scope is None""" + logger = Logger() + logger.no_store = False + logger.log_message("INFO", "Test", scope=None, user=None, type=Logger.LOG, url=None) + + mock_store.write_topic.assert_called_once() + call_args = mock_store.write_topic.call_args + self.assertEqual(call_args[0][0], "NOSCOPE__openc3_log_messages") + + @patch("openc3.utilities.logger.EphemeralStoreQueued") + def test_log_message_does_not_write_to_store_when_no_store_true(self, mock_store): + """Test that log messages are not written to store when no_store is True""" + logger = Logger() + logger.no_store = True + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url=None) + + mock_store.write_topic.assert_not_called() + + def test_log_message_timestamp_format(self): + """Test that timestamp is in correct ISO format with Z suffix""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url=None) + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + timestamp = data["@timestamp"] + # Verify format: YYYY-MM-DDTHH:MM:SS.ffffffZ + self.assertTrue(timestamp.endswith("Z")) + self.assertIn("T", timestamp) + # Should be parseable + from datetime import datetime + parsed = datetime.fromisoformat(timestamp.replace("Z", "+00:00")) + self.assertIsNotNone(parsed) + + def test_log_message_time_is_nanoseconds(self): + """Test that time field is in nanoseconds""" + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + before_ns = time.time_ns() + logger.log_message("INFO", "Test", scope="TEST", user=None, type=Logger.LOG, url=None) + after_ns = time.time_ns() + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + data = json.loads(output) + log_time = data["time"] + # Verify it's in the expected range (nanoseconds) + self.assertGreaterEqual(log_time, before_ns) + self.assertLessEqual(log_time, after_ns) + + def test_log_message_thread_safety(self): + """Test that log_message is thread-safe with mutex""" + import threading + orig_stdout = sys.stdout + sys.stdout = StringIO() + + logger = Logger() + results = [] + + def log_from_thread(n): + logger.log_message("INFO", f"Message {n}", scope="TEST", user=None, type=Logger.LOG, url=None) + + threads = [threading.Thread(target=log_from_thread, args=(i,)) for i in range(10)] + for t in threads: + t.start() + for t in threads: + t.join() + + output = sys.stdout.getvalue() + sys.stdout = orig_stdout + + lines = output.strip().split("\n") + self.assertEqual(len(lines), 10) + # Each line should be valid JSON + for line in lines: + data = json.loads(line) + self.assertIn("Message", data["message"]) diff --git a/openc3/spec/utilities/logger_spec.rb b/openc3/spec/utilities/logger_spec.rb index 9e944eeb09..e75f71de22 100644 --- a/openc3/spec/utilities/logger_spec.rb +++ b/openc3/spec/utilities/logger_spec.rb @@ -166,5 +166,323 @@ def test_no_output(level, method, block = false) test_output(Logger::FATAL, 'fatal', true) end end + + describe "log_message with OPENC3_LOG_STDERR" do + before(:each) do + Logger.level = Logger::DEBUG + ENV.delete('OPENC3_LOG_STDERR') + end + + after(:each) do + ENV.delete('OPENC3_LOG_STDERR') + $stdout = STDOUT + $stderr = STDERR + end + + # Helper method to setup StringIO streams + def setup_streams + stdout = StringIO.new('', 'r+') + stderr = StringIO.new('', 'r+') + $stdout = stdout + $stderr = stderr + [stdout, stderr] + end + + context "when OPENC3_LOG_STDERR is not set" do + it "logs all levels to stdout" do + stdout, stderr = setup_streams + + Logger.debug("Debug message") + Logger.info("Info message") + Logger.warn("Warn message") + Logger.error("Error message") + Logger.fatal("Fatal message") + + # All messages should go to stdout + output_lines = stdout.string.lines + expect(output_lines.length).to eq(5) + expect(output_lines[0]).to include('Debug message') + expect(output_lines[1]).to include('Info message') + expect(output_lines[2]).to include('Warn message') + expect(output_lines[3]).to include('Error message') + expect(output_lines[4]).to include('Fatal message') + + # Nothing should go to stderr + expect(stderr.string).to be_empty + end + end + + # Test truthy values that enable stderr routing + ['true', '1', 'yes', 'on', 'TRUE', 'YeS'].each do |truthy_value| + context "when OPENC3_LOG_STDERR is set to '#{truthy_value}'" do + it "logs warn, error, and fatal to stderr" do + ENV['OPENC3_LOG_STDERR'] = truthy_value + stdout, stderr = setup_streams + + Logger.debug("Debug message") + Logger.info("Info message") + Logger.warn("Warn message") + Logger.error("Error message") + Logger.fatal("Fatal message") + + # Debug and info should go to stdout + stdout_lines = stdout.string.lines + expect(stdout_lines.length).to eq(2) + expect(stdout_lines[0]).to include('Debug message') + expect(stdout_lines[1]).to include('Info message') + + # Warn, error, and fatal should go to stderr + stderr_lines = stderr.string.lines + expect(stderr_lines.length).to eq(3) + expect(stderr_lines[0]).to include('Warn message') + expect(stderr_lines[1]).to include('Error message') + expect(stderr_lines[2]).to include('Fatal message') + end + end + end + + # Test falsy values that keep all logs on stdout + [['false', 'Warn message', :warn], + ['0', 'Error message', :error], + ['', 'Fatal message', :fatal], + ['arbitrary', 'Warn message', :warn]].each do |env_value, message, level| + context "when OPENC3_LOG_STDERR is set to '#{env_value}'" do + it "logs all levels to stdout" do + ENV['OPENC3_LOG_STDERR'] = env_value + stdout, stderr = setup_streams + + Logger.send(level, message) + + # Message should go to stdout (not a recognized truthy value) + expect(stdout.string).to include(message) + expect(stderr.string).to be_empty + end + end + end + + context "JSON format verification with stderr" do + it "outputs valid JSON to stderr when enabled" do + ENV['OPENC3_LOG_STDERR'] = 'true' + stdout, stderr = setup_streams + + Logger.error("Test error message") + + # Verify JSON is valid and contains expected fields + json = JSON.parse(stderr.string, allow_nan: true, create_additions: true) + expect(json['level']).to eq('ERROR') + expect(json['message']).to eq('Test error message') + expect(json).to have_key('time') + expect(json).to have_key('@timestamp') + expect(json).to have_key('container_name') + end + end + end + + describe "log_message with other parameter" do + before(:each) do + Logger.level = Logger::INFO + end + + after(:each) do + $stdout = STDOUT + end + + def setup_stdout + stdout = StringIO.new('', 'r+') + $stdout = stdout + stdout + end + + context "with nested hash" do + it "merges nested hash into log data" do + stdout = setup_stdout + + other = { + request_id: '12345', + metadata: { + source: 'test', + version: '1.0' + } + } + + Logger.info("Test message", other: other) + + json = JSON.parse(stdout.string, allow_nan: true, create_additions: true) + expect(json['message']).to eq('Test message') + expect(json['request_id']).to eq('12345') + expect(json['metadata']).to be_a(Hash) + expect(json['metadata']['source']).to eq('test') + expect(json['metadata']['version']).to eq('1.0') + end + end + + context "with array values" do + it "includes array values in log data" do + stdout = setup_stdout + + other = { + tags: ['error', 'critical', 'alert'], + items: [1, 2, 3] + } + + Logger.warn("Warning message", other: other) + + json = JSON.parse(stdout.string, allow_nan: true, create_additions: true) + expect(json['tags']).to eq(['error', 'critical', 'alert']) + expect(json['items']).to eq([1, 2, 3]) + end + end + + context "with Time objects" do + it "converts Time objects to strings" do + stdout = setup_stdout + + time = Time.parse("2025-01-15 12:30:45 UTC") + other = { + start_time: time, + end_time: time + 3600 + } + + Logger.info("Time test", other: other) + + json = JSON.parse(stdout.string, allow_nan: true, create_additions: true) + expect(json['start_time']).to be_a(String) + expect(json['end_time']).to be_a(String) + end + end + + context "with Symbol values" do + it "converts symbols to strings" do + stdout = setup_stdout + + other = { + status: :success, + operation: :read + } + + Logger.info("Symbol test", other: other) + + json = JSON.parse(stdout.string, allow_nan: true, create_additions: true) + expect(json['status']).to eq('success') + expect(json['operation']).to eq('read') + end + end + + context "with special float values" do + it "handles Infinity, -Infinity, and NaN" do + stdout = setup_stdout + + other = { + pos_infinity: Float::INFINITY, + neg_infinity: -Float::INFINITY, + not_a_number: Float::NAN + } + + Logger.info("Float test", other: other) + + # When create_additions: true, the special floats are reconstructed + json = JSON.parse(stdout.string, allow_nan: true, create_additions: true) + expect(json['pos_infinity']).to eq(Float::INFINITY) + expect(json['neg_infinity']).to eq(-Float::INFINITY) + expect(json['not_a_number'].nan?).to be true + + # Verify the raw JSON contains the special representation + raw_output = stdout.string + expect(raw_output).to include('"json_class":"Float"') + expect(raw_output).to include('"raw":"Infinity"') + expect(raw_output).to include('"raw":"-Infinity"') + expect(raw_output).to include('"raw":"NaN"') + end + end + + context "with Exception object" do + it "serializes exception details" do + stdout = setup_stdout + + begin + raise StandardError.new("Test error") + rescue => e + other = { + exception: e + } + + Logger.error("Exception occurred", other: other) + end + + json = JSON.parse(stdout.string, allow_nan: true, create_additions: true) + expect(json['exception']).to be_a(Hash) + expect(json['exception']['class']).to eq('StandardError') + expect(json['exception']['message']).to eq('Test error') + expect(json['exception']['backtrace']).to be_a(Array) + end + end + + context "with Regexp values" do + it "converts regexp to string" do + stdout = setup_stdout + + other = { + pattern: /test.*pattern/i + } + + Logger.info("Regexp test", other: other) + + json = JSON.parse(stdout.string, allow_nan: true, create_additions: true) + expect(json['pattern']).to eq('(?i-mx:test.*pattern)') + end + end + + context "with mixed complex types" do + it "handles deeply nested structures with various types" do + stdout = setup_stdout + + other = { + request: { + id: 'req-123', + timestamp: Time.now.utc, + params: ['param1', 'param2'], + flags: { + debug: true, + verbose: false, + level: :high + } + }, + metrics: { + duration: 123.45, + count: 10 + } + } + + Logger.info("Complex test", other: other) + + json = JSON.parse(stdout.string, allow_nan: true, create_additions: true) + expect(json['request']).to be_a(Hash) + expect(json['request']['id']).to eq('req-123') + expect(json['request']['params']).to eq(['param1', 'param2']) + expect(json['request']['flags']['level']).to eq('high') + expect(json['metrics']['duration']).to eq(123.45) + expect(json['metrics']['count']).to eq(10) + end + end + + context "with nil and empty values" do + it "handles nil values correctly" do + stdout = setup_stdout + + other = { + value1: nil, + value2: '', + value3: [] + } + + Logger.info("Nil test", other: other) + + json = JSON.parse(stdout.string, allow_nan: true, create_additions: true) + expect(json['value1']).to be_nil + expect(json['value2']).to eq('') + expect(json['value3']).to eq([]) + end + end + end end end