1+ # Copyright 2025 Amazon.com, Inc. or its affiliates. All Rights Reserved.
2+ # SPDX-License-Identifier: Apache-2.0
3+ 4+ """Test that Firecracker works correctly when instrumented with tracing and trace level logs are enabled.
5+
6+ This test verifies that the log-instrument crate can successfully instrument the actual Firecracker
7+ binary and that the instrumented Firecracker works correctly with trace-level logging.
8+
9+ Test Coverage:
10+ 1. Uses clippy-tracing tool to add instrumentation to Firecracker source files
11+ 2. Builds Firecracker with tracing features enabled
12+ 3. Verifies basic functionality (API calls, VM lifecycle) works with instrumentation
13+ 4. Confirms trace-level logs are generated and contain meaningful information
14+ 5. Checks performance impact is within acceptable bounds
15+ """
16+ 17+ import re
18+ import tempfile
19+ import time
20+ from pathlib import Path
21+ 22+ import pytest
23+ 24+ from framework import utils
25+ from framework .microvm import MicroVMFactory
26+ from host_tools .cargo_build import cargo , get_binary
27+ 28+ 29+ def build_instrumented_firecracker ():
30+ """Build Firecracker with tracing instrumentation enabled."""
31+ # First, add instrumentation using clippy-tracing
32+ clippy_tracing = get_binary ("clippy-tracing" )
33+ 34+ # Add instrumentation to a subset of files to avoid performance issues
35+ # We'll instrument just the API server and main entry points for meaningful traces
36+ cargo_args = [
37+ "--action" ,
38+ "fix" ,
39+ "--path" ,
40+ "./src/firecracker/src/main.rs" ,
41+ "--path" ,
42+ "./src/firecracker/src/api_server" ,
43+ "--path" ,
44+ "./src/vmm/src/lib.rs" ,
45+ "--path" ,
46+ "./src/vmm/src/builder.rs" ,
47+ ]
48+ 49+ utils .check_output (f"{ clippy_tracing } { ' ' .join (cargo_args )} )
50+ 51+ # Build Firecracker with tracing feature enabled
52+ cargo ("build" , "--features tracing --bin firecracker" )
53+ 54+ return get_binary ("firecracker" )
55+ 56+ 57+ def cleanup_instrumentation ():
58+ """Remove instrumentation from source files."""
59+ clippy_tracing = get_binary ("clippy-tracing" )
60+ 61+ # Strip instrumentation from the files we modified
62+ strip_args = [
63+ "--action" ,
64+ "strip" ,
65+ "--path" ,
66+ "./src/firecracker/src/main.rs" ,
67+ "--path" ,
68+ "./src/firecracker/src/api_server" ,
69+ "--path" ,
70+ "./src/vmm/src/lib.rs" ,
71+ "--path" ,
72+ "./src/vmm/src/builder.rs" ,
73+ ]
74+ 75+ utils .check_output (f"{ clippy_tracing } { ' ' .join (strip_args )} )
76+ 77+ 78+ @pytest .fixture (scope = "module" )
79+ def instrumented_firecracker_binary ():
80+ """Build instrumented Firecracker binary for testing."""
81+ binary = build_instrumented_firecracker ()
82+ yield binary
83+ cleanup_instrumentation ()
84+ 85+ 86+ def test_firecracker_tracing_basic_functionality (instrumented_firecracker_binary ):
87+ """Test that instrumented Firecracker can start and handle basic API calls with trace logging."""
88+ # Create a temporary directory for this test
89+ with tempfile .TemporaryDirectory () as temp_dir :
90+ # Create a MicroVM factory with the instrumented binary
91+ factory = MicroVMFactory (instrumented_firecracker_binary )
92+ 93+ # Build a microVM
94+ vm = factory .build ()
95+ 96+ # Configure basic VM settings
97+ vm .basic_config (vcpu_count = 1 , mem_size_mib = 128 )
98+ 99+ # Spawn the VM with trace level logging
100+ vm .spawn (log_level = "Trace" , log_show_level = True , log_show_origin = True )
101+ 102+ try :
103+ # Wait for the API socket to be available
104+ vm ._wait_for_api_socket () # pylint: disable=protected-access
105+ 106+ # Make some basic API calls to generate trace logs
107+ # Get instance info
108+ response = vm .api .describe_instance .get ()
109+ assert response .status_code == 200
110+ 111+ # Get machine config
112+ response = vm .api .machine_config .get ()
113+ assert response .status_code == 200
114+ 115+ # Set logger to trace level to ensure we capture instrumentation logs
116+ logger_config = {"level" : "Trace" }
117+ response = vm .api .logger .put (** logger_config )
118+ assert response .status_code == 204
119+ 120+ # Make another API call after setting trace level
121+ response = vm .api .describe_instance .get ()
122+ assert response .status_code == 200
123+ 124+ # Verify that the VM is working correctly
125+ assert vm .state == "Not started"
126+ 127+ finally :
128+ vm .kill ()
129+ 130+ # Check the logs for instrumentation traces
131+ log_data = vm .log_data
132+ 133+ # Verify that trace level logs are present
134+ assert "TRACE" in log_data , "Expected TRACE level logs in output"
135+ 136+ # Look for log-instrument traces (function entry/exit)
137+ # These should have the format: ThreadId(X)>>function_name or ThreadId(X)<<function_name
138+ trace_pattern = r"ThreadId\(\d+\)(?:::[^>]*)?(?:>>|<<)\w+"
139+ trace_matches = re .findall (trace_pattern , log_data )
140+ 141+ assert (
142+ len (trace_matches ) > 0
143+ ), f"Expected to find log-instrument traces in logs, but found none. Log data: { log_data [:1000 ]}
144+ 145+ # Verify we see function entry and exit traces
146+ entry_traces = [match for match in trace_matches if ">>" in match ]
147+ exit_traces = [match for match in trace_matches if "<<" in match ]
148+ 149+ assert len (entry_traces ) > 0 , "Expected to find function entry traces (>>)"
150+ assert len (exit_traces ) > 0 , "Expected to find function exit traces (<<)"
151+ 152+ # Verify that meaningful functions are being traced
153+ # Look for traces from main, API handling, or VM management functions
154+ meaningful_functions = ["main" , "api" , "vmm" , "request" , "response" ]
155+ found_meaningful = False
156+ 157+ for trace in trace_matches :
158+ for func in meaningful_functions :
159+ if func .lower () in trace .lower ():
160+ found_meaningful = True
161+ break
162+ if found_meaningful :
163+ break
164+ 165+ assert (
166+ found_meaningful
167+ ), f"Expected to find traces from meaningful functions, but traces were: { trace_matches [:10 ]}
168+ 169+ 170+ def test_firecracker_tracing_performance_impact ():
171+ """Test that instrumented Firecracker still performs reasonably (basic smoke test)."""
172+ # This is a basic performance smoke test to ensure tracing doesn't break functionality
173+ # We're not doing detailed performance analysis, just ensuring it doesn't hang or crash
174+ 175+ # Build instrumented binary
176+ instrumented_binary = build_instrumented_firecracker ()
177+ 178+ try :
179+ factory = MicroVMFactory (instrumented_binary )
180+ vm = factory .build ()
181+ 182+ # Time the basic configuration and startup
183+ start_time = time .time ()
184+ 185+ vm .basic_config (vcpu_count = 1 , mem_size_mib = 128 , add_root_device = False )
186+ vm .spawn (log_level = "Trace" )
187+ 188+ # Make several API calls
189+ for _ in range (5 ):
190+ response = vm .api .describe_instance .get ()
191+ assert response .status_code == 200
192+ 193+ elapsed = time .time () - start_time
194+ 195+ # Should complete within reasonable time (30 seconds is very generous)
196+ # This is just to catch major performance regressions or hangs
197+ assert (
198+ elapsed < 30
199+ ), f"Instrumented Firecracker took too long to start and handle API calls: { elapsed }
200+ 201+ vm .kill ()
202+ 203+ finally :
204+ cleanup_instrumentation ()
205+ 206+ 207+ def test_trace_log_filtering ():
208+ """Test that trace log filtering works correctly with instrumented Firecracker."""
209+ instrumented_binary = build_instrumented_firecracker ()
210+ 211+ try :
212+ factory = MicroVMFactory (instrumented_binary )
213+ vm = factory .build ()
214+ 215+ vm .basic_config (vcpu_count = 1 , mem_size_mib = 128 , add_root_device = False )
216+ vm .spawn (log_level = "Info" ) # Start with Info level
217+ 218+ try :
219+ # Initially should not have trace logs
220+ initial_log_data = vm .log_data
221+ 222+ # Set logger to trace level
223+ logger_config = {"level" : "Trace" }
224+ response = vm .api .logger .put (** logger_config )
225+ assert response .status_code == 204
226+ 227+ # Make API calls to generate traces
228+ for _ in range (3 ):
229+ response = vm .api .describe_instance .get ()
230+ assert response .status_code == 200
231+ 232+ # Now should have trace logs
233+ final_log_data = vm .log_data
234+ 235+ # Verify no TRACE logs were present initially
236+ assert (
237+ "TRACE" not in initial_log_data
238+ ), "Expected no TRACE logs before setting log level to Trace"
239+ 240+ # The new log data should contain trace information
241+ new_log_data = final_log_data [len (initial_log_data ) :]
242+ assert (
243+ "TRACE" in new_log_data
244+ ), "Expected TRACE logs after setting log level to Trace"
245+ 246+ finally :
247+ vm .kill ()
248+ 249+ finally :
250+ cleanup_instrumentation ()
0 commit comments