diff --git a/ironic_python_agent/api/app.py b/ironic_python_agent/api/app.py index f646b95c9..871f980eb 100644 --- a/ironic_python_agent/api/app.py +++ b/ironic_python_agent/api/app.py @@ -22,6 +22,7 @@ import werkzeug from werkzeug import exceptions as http_exc from werkzeug import routing +from ironic_python_agent.api import request_log from ironic_python_agent import encoding from ironic_python_agent.metrics_lib import metrics_utils @@ -137,7 +138,10 @@ class Application(object): bind_addr = (self.agent.listen_address.hostname, self.agent.listen_address.port) - server = wsgi.Server(bind_addr=bind_addr, wsgi_app=self, + # Wrap the application with request logging middleware + wsgi_app = request_log.RequestLogMiddleware(self) + + server = wsgi.Server(bind_addr=bind_addr, wsgi_app=wsgi_app, server_name='ironic-python-agent') if self.tls_cert_file and self.tls_key_file: diff --git a/ironic_python_agent/api/request_log.py b/ironic_python_agent/api/request_log.py new file mode 100644 index 000000000..71159adac --- /dev/null +++ b/ironic_python_agent/api/request_log.py @@ -0,0 +1,93 @@ +# 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. +""" +Middleware to log API request details including timing, status codes, +and request information for debugging purposes. +""" +import collections.abc +import time + +from oslo_log import log + +LOG = log.getLogger('ironic_python_agent.api') + + +def get_real_ip(environ): + """Safely retrieves the real IP address from a WSGI request.""" + # Check for the X-Forwarded-For header, which can contain a list of IPs. + # The client's IP is the first one in the list. + if 'HTTP_X_FORWARDED_FOR' in environ: + # The header value is a comma-separated string, e.g., "client, proxy" + # We take the first IP, which is the original client. + return environ['HTTP_X_FORWARDED_FOR'].split(',')[0].strip() + + # If X-Forwarded-For is not present, check for X-Real-IP. + elif 'HTTP_X_REAL_IP' in environ: + return environ['HTTP_X_REAL_IP'] + + # If no proxy headers are present, fall back to REMOTE_ADDR. + else: + return environ.get('REMOTE_ADDR') + + +class RequestLogMiddleware(object): + """Middleware to log request details for debugging.""" + + def __init__(self, app): + self.app = app + + def __call__(self, environ, start_response): + # Capture request start time + start_time = time.time() + + # Extract request details + method = environ.get('REQUEST_METHOD', '') + path = environ.get('PATH_INFO', '') + query_string = environ.get('QUERY_STRING', '') + + # Build full path with query string if present + full_path = path + if query_string: + full_path = f"{path}?{query_string}" + + # Capture response status + status_code = None + + def logging_start_response(status, headers, exc_info=None): + nonlocal status_code + # Extract status code from status string (e.g., "200 OK") + try: + status_code = int(status.split(' ', 1)[0]) + except (ValueError, IndexError): + status_code = 0 + return start_response(status, headers, exc_info) + + # Process the request + try: + response = self.app(environ, logging_start_response) + # Ensure response is consumed if it's a generator + if isinstance(response, collections.abc.Iterator): + response = list(response) + return response + finally: + # Calculate request duration + duration = time.time() - start_time + duration_ms = round(duration * 1000, 2) + + # Log the request details with request ID for traceability + LOG.info("%(source_ip)s - %(method)s %(path)s - %(status)s (%(" + "duration)sms)", + {'method': method, + 'path': full_path, + 'status': status_code or 'unknown', + 'duration': duration_ms, + 'source_ip': get_real_ip(environ) or 'unknown'}) diff --git a/ironic_python_agent/tests/unit/test_request_log_middleware.py b/ironic_python_agent/tests/unit/test_request_log_middleware.py new file mode 100644 index 000000000..90bc9d728 --- /dev/null +++ b/ironic_python_agent/tests/unit/test_request_log_middleware.py @@ -0,0 +1,353 @@ +# 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. +""" +Tests for the RequestLogMiddleware +""" + +from unittest import mock + +from ironic_python_agent.api import request_log +from ironic_python_agent.tests.unit import base + + +class TestRequestLogMiddleware(base.IronicAgentTest): + """Test cases for RequestLogMiddleware.""" + + def setUp(self): + super(TestRequestLogMiddleware, self).setUp() + + # Create a mock application + self.mock_app = mock.Mock() + self.mock_app.return_value = [b'response body'] + + # Create the middleware instance + self.middleware = request_log.RequestLogMiddleware(self.mock_app) + + # Mock the logger + self.mock_log = mock.patch.object( + request_log, 'LOG', autospec=True + ).start() + + self.template = ("%(source_ip)s - %(method)s %(path)s - %(status)s " + "(%(duration)sms)") + + # Mock time for consistent timing tests + self.mock_time = mock.patch.object( + request_log, 'time', autospec=True + ).start() + self.mock_time.time.side_effect = [1000.0, 1000.5] # 500ms duration + + def test_successful_get_request(self): + """Test logging of a successful GET request.""" + environ = { + 'REQUEST_METHOD': 'GET', + 'PATH_INFO': '/v1/status', + 'QUERY_STRING': '' + } + + def start_response(status, headers, exc_info=None): + return None + + # Configure mock app to call start_response with 200 OK + def mock_app_call(env, sr): + sr('200 OK', [('Content-Type', 'application/json')]) + return [b'response'] + + self.mock_app.side_effect = mock_app_call + + # Call the middleware + response = self.middleware(environ, start_response) + + # Verify the response is returned correctly + self.assertEqual(response, [b'response']) + + # Verify the log was called with correct parameters + self.mock_log.info.assert_called_once_with( + self.template, + {'method': 'GET', + 'path': '/v1/status', + 'status': 200, + 'duration': 500.0, + 'source_ip': 'unknown'} + ) + + def test_post_request_with_query_string(self): + """Test logging of a POST request with query parameters.""" + environ = { + 'REQUEST_METHOD': 'POST', + 'PATH_INFO': '/v1/commands/', + 'QUERY_STRING': 'wait=true&agent_token=abc' + } + + def start_response(status, headers, exc_info=None): + return None + + def mock_app_call(env, sr): + sr('201 Created', [('Content-Type', 'application/json')]) + return [b'created'] + + self.mock_app.side_effect = mock_app_call + + response = self.middleware(environ, start_response) + + self.assertEqual(response, [b'created']) + + self.mock_log.info.assert_called_once_with( + self.template, + {'method': 'POST', + 'path': '/v1/commands/?wait=true&agent_token=abc', + 'status': 201, + 'duration': 500.0, + 'source_ip': 'unknown'} + ) + + def test_error_response(self): + """Test logging of an error response.""" + environ = { + 'REQUEST_METHOD': 'GET', + 'PATH_INFO': '/v1/commands/123', + 'QUERY_STRING': '' + } + + def start_response(status, headers, exc_info=None): + return None + + def mock_app_call(env, sr): + sr('404 Not Found', [('Content-Type', 'application/json')]) + return [b'not found'] + + self.mock_app.side_effect = mock_app_call + + response = self.middleware(environ, start_response) + + self.assertEqual(response, [b'not found']) + + self.mock_log.info.assert_called_once_with( + self.template, + {'method': 'GET', + 'path': '/v1/commands/123', + 'status': 404, + 'duration': 500.0, + 'source_ip': 'unknown'} + ) + + def test_invalid_status_code(self): + """Test handling of invalid status code.""" + environ = { + 'REQUEST_METHOD': 'GET', + 'PATH_INFO': '/v1/status', + 'QUERY_STRING': '' + } + + def start_response(status, headers, exc_info=None): + return None + + def mock_app_call(env, sr): + sr('INVALID', []) # Invalid status format + return [b'response'] + + self.mock_app.side_effect = mock_app_call + + response = self.middleware(environ, start_response) + + self.assertEqual(response, [b'response']) + + # Should log with status 'unknown' for invalid status + self.mock_log.info.assert_called_once_with( + self.template, + {'method': 'GET', + 'path': '/v1/status', + 'status': 'unknown', + 'duration': 500.0, + 'source_ip': 'unknown'} + ) + + def test_generator_response(self): + """Test handling of generator responses.""" + environ = { + 'REQUEST_METHOD': 'GET', + 'PATH_INFO': '/v1/status', + 'QUERY_STRING': '' + } + + def start_response(status, headers, exc_info=None): + return None + + def response_generator(): + yield b'part1' + yield b'part2' + + def mock_app_call(env, sr): + sr('200 OK', []) + return response_generator() + + self.mock_app.side_effect = mock_app_call + + response = self.middleware(environ, start_response) + + # Response should be consumed and converted to list + self.assertEqual(response, [b'part1', b'part2']) + + self.mock_log.info.assert_called_once() + + def test_missing_environ_values(self): + """Test handling of missing environ values.""" + environ = {} # Empty environ + + def start_response(status, headers, exc_info=None): + return None + + def mock_app_call(env, sr): + sr('200 OK', []) + return [b'response'] + + self.mock_app.side_effect = mock_app_call + + response = self.middleware(environ, start_response) + + self.assertEqual(response, [b'response']) + + # Should use empty strings for missing values + self.mock_log.info.assert_called_once_with( + self.template, + {'method': '', + 'path': '', + 'status': 200, + 'duration': 500.0, + 'source_ip': 'unknown'} + ) + + def test_request_with_remote_addr(self): + """Test logging with REMOTE_ADDR present.""" + environ = { + 'REQUEST_METHOD': 'GET', + 'PATH_INFO': '/v1/status', + 'QUERY_STRING': '', + 'REMOTE_ADDR': '192.168.1.100' + } + + def start_response(status, headers, exc_info=None): + return None + + def mock_app_call(env, sr): + sr('200 OK', []) + return [b'response'] + + self.mock_app.side_effect = mock_app_call + + response = self.middleware(environ, start_response) + + self.assertEqual(response, [b'response']) + + # Should log with source IP + self.mock_log.info.assert_called_once_with( + self.template, + {'method': 'GET', + 'path': '/v1/status', + 'status': 200, + 'duration': 500.0, + 'source_ip': '192.168.1.100'} + ) + + def test_request_with_x_forwarded_for(self): + """Test logging with X-Forwarded-For header.""" + environ = { + 'REQUEST_METHOD': 'GET', + 'PATH_INFO': '/v1/status', + 'QUERY_STRING': '', + 'REMOTE_ADDR': '10.0.0.1', + 'HTTP_X_FORWARDED_FOR': '192.168.1.100, 10.0.0.2' + } + + def start_response(status, headers, exc_info=None): + return None + + def mock_app_call(env, sr): + sr('200 OK', []) + return [b'response'] + + self.mock_app.side_effect = mock_app_call + + response = self.middleware(environ, start_response) + + self.assertEqual(response, [b'response']) + + # Should use first IP from X-Forwarded-For + self.mock_log.info.assert_called_once_with( + self.template, + {'method': 'GET', + 'path': '/v1/status', + 'status': 200, + 'duration': 500.0, + 'source_ip': '192.168.1.100'} + ) + + def test_request_with_x_real_ip(self): + """Test logging with X-Real-IP header.""" + environ = { + 'REQUEST_METHOD': 'GET', + 'PATH_INFO': '/v1/status', + 'QUERY_STRING': '', + 'REMOTE_ADDR': '10.0.0.1', + 'HTTP_X_REAL_IP': '192.168.1.100' + } + + def start_response(status, headers, exc_info=None): + return None + + def mock_app_call(env, sr): + sr('200 OK', []) + return [b'response'] + + self.mock_app.side_effect = mock_app_call + + response = self.middleware(environ, start_response) + + self.assertEqual(response, [b'response']) + + # Should use X-Real-IP + self.mock_log.info.assert_called_once_with( + self.template, + {'method': 'GET', + 'path': '/v1/status', + 'status': 200, + 'duration': 500.0, + 'source_ip': '192.168.1.100'} + ) + + def test_exception_still_logs(self): + """Test that logging happens even if app raises exception.""" + environ = { + 'REQUEST_METHOD': 'GET', + 'PATH_INFO': '/v1/status', + 'QUERY_STRING': '' + } + + def start_response(status, headers, exc_info=None): + return None + + # Mock app raises an exception + self.mock_app.side_effect = ValueError("Test error") + + # The middleware should re-raise the exception but still log + self.assertRaises(ValueError, self.middleware, environ, start_response) + + # Verify the log was still called (with unknown status since + # start_response was never called) + self.mock_log.info.assert_called_once_with( + self.template, + {'method': 'GET', + 'path': '/v1/status', + 'status': 'unknown', + 'duration': 500.0, + 'source_ip': 'unknown'} + )