|
| 1 | +# Copyright 2025 Amazon.com, Inc. or its affiliates. All Rights Reserved. |
| 2 | +# SPDX-License-Identifier: Apache-2.0 |
| 3 | + |
| 4 | +""" |
| 5 | +Integration test verifying that Firecracker builds and runs correctly when instrumented |
| 6 | +with the `log_instrument::instrument` macro. Ensures that TRACE-level logs and entry/exit |
| 7 | +markers (ThreadId(...) >> / <<) are emitted when the binary is built with the `tracing` |
| 8 | +feature. |
| 9 | +""" |
| 10 | + |
| 11 | +import platform |
| 12 | +import re |
| 13 | +from pathlib import Path |
| 14 | + |
| 15 | +import pytest |
| 16 | + |
| 17 | +from framework import utils |
| 18 | +from host_tools.cargo_build import cargo, get_binary |
| 19 | + |
| 20 | +# Typical markers emitted by the `log_instrument` macro |
| 21 | +TRACE_LEVEL_HINT = "TRACE" |
| 22 | +MARKER_REGEX = re.compile(r"ThreadId\(\d+\).*?(?:>>|<<)") |
| 23 | +PATHS_TO_INSTRUMENT = [ |
| 24 | + "../src/firecracker/src/main.rs", |
| 25 | + "../src/firecracker/src/api_server", |
| 26 | + "../src/vmm/src/lib.rs", |
| 27 | + "../src/vmm/src/builder.rs", |
| 28 | +] |
| 29 | +TMP_BUILD_DIR = "../test_instrumented_firecracker_build" |
| 30 | +ARCH_STR = f"{platform.machine()}" |
| 31 | + |
| 32 | + |
| 33 | +def build_instrumented_binary(): |
| 34 | + """Builds an instrumented Firecracker binary with tracing instrumentation.""" |
| 35 | + # we need a different directory to avoid overriding the main bin |
| 36 | + instrumented_binary_dir = ( |
| 37 | + Path(TMP_BUILD_DIR) / f"{ARCH_STR}-unknown-linux-musl" / "release" |
| 38 | + ) |
| 39 | + |
| 40 | + clippy_tracing = get_binary("clippy-tracing") |
| 41 | + for p in PATHS_TO_INSTRUMENT: |
| 42 | + utils.check_output( |
| 43 | + f"{clippy_tracing} --action fix --suffix log_instrument:: --cfg-attr 'feature =\"tracing\"' --path {p}" |
| 44 | + ) |
| 45 | + cargo( |
| 46 | + "build", |
| 47 | + f"--workspace --target {platform.machine()}-unknown-linux-musl --release " |
| 48 | + f"--features tracing --bin firecracker", |
| 49 | + env={"CARGO_TARGET_DIR": TMP_BUILD_DIR}, |
| 50 | + ) |
| 51 | + return get_binary("firecracker", binary_dir=instrumented_binary_dir) |
| 52 | + |
| 53 | + |
| 54 | +def cleanup_instrumentation(): |
| 55 | + """Cleans up tracing instrumentation from the Firecracker binary.""" |
| 56 | + clippy_tracing = get_binary("clippy-tracing") |
| 57 | + for p in PATHS_TO_INSTRUMENT: |
| 58 | + utils.check_output( |
| 59 | + f"{clippy_tracing} --action strip --suffix log_instrument:: --cfg-attr 'feature =\"tracing\"' --path {p}" |
| 60 | + ) |
| 61 | + |
| 62 | + |
| 63 | +@pytest.fixture(scope="module") |
| 64 | +def instrumented_binary(): |
| 65 | + """Build and provide the path to an instrumented Firecracker binary.""" |
| 66 | + binary_path = build_instrumented_binary() |
| 67 | + yield binary_path |
| 68 | + cleanup_instrumentation() |
| 69 | + |
| 70 | + |
| 71 | +def test_log_instrument_firecracker_basic_functionality( |
| 72 | + instrumented_binary, microvm_factory |
| 73 | +): |
| 74 | + """Test that instrumented Firecracker can start and handle basic API calls with trace logging.""" |
| 75 | + vm = microvm_factory.build(fc_binary_path=instrumented_binary) |
| 76 | + vm.spawn(log_level="Info", log_show_level=True, log_show_origin=True) |
| 77 | + |
| 78 | + # Generate some log traffic |
| 79 | + _ = vm.api.describe.get() |
| 80 | + _ = vm.api.machine_config.get() |
| 81 | + |
| 82 | + pre_tracing_log_data = vm.log_data |
| 83 | + |
| 84 | + # Ensure TRACE logs are being captured |
| 85 | + logger_config = { |
| 86 | + "level": "Trace", |
| 87 | + "show_level": True, |
| 88 | + "show_log_origin": True, |
| 89 | + } |
| 90 | + _ = vm.api.logger.put(**logger_config) |
| 91 | + |
| 92 | + # Another API call after enabling TRACE |
| 93 | + _ = vm.api.describe.get() |
| 94 | + |
| 95 | + assert ( |
| 96 | + TRACE_LEVEL_HINT not in pre_tracing_log_data |
| 97 | + ), "TRACE level logs were found before setting log level to TRACE. " |
| 98 | + |
| 99 | + pre_tracing_log_matches = re.findall(MARKER_REGEX, pre_tracing_log_data) |
| 100 | + |
| 101 | + assert ( |
| 102 | + len(pre_tracing_log_matches) == 0 |
| 103 | + ), f"Expected no log-instrument traces in logs before enabling TRACE, but found: {pre_tracing_log_matches}" |
| 104 | + |
| 105 | + post_tracing_log_data = vm.log_data |
| 106 | + |
| 107 | + assert ( |
| 108 | + TRACE_LEVEL_HINT in post_tracing_log_data |
| 109 | + ), "Expected TRACE level logs in output" |
| 110 | + |
| 111 | + post_tracing_log_matches = re.findall(MARKER_REGEX, post_tracing_log_data) |
| 112 | + |
| 113 | + assert ( |
| 114 | + len(post_tracing_log_matches) > 0 |
| 115 | + ), f"Expected to find log-instrument traces in logs, but found none. Log data: {post_tracing_log_data[:1000]}..." |
| 116 | + |
| 117 | + entry_traces = [match for match in post_tracing_log_matches if ">>" in match] |
| 118 | + exit_traces = [match for match in post_tracing_log_matches if "<<" in match] |
| 119 | + |
| 120 | + assert len(entry_traces) > 0, "Expected to find function entry traces (>>)" |
| 121 | + assert len(exit_traces) > 0, "Expected to find function exit traces (<<)" |
| 122 | + |
| 123 | + meaningful_keywords = ["vmm", "request", "response"] |
| 124 | + |
| 125 | + # Ensure that each of the meaningful keywords is present in at least one trace |
| 126 | + # match from the post-tracing logs. |
| 127 | + assert all( |
| 128 | + any(keyword.lower() in trace.lower() for trace in post_tracing_log_matches) |
| 129 | + for keyword in meaningful_keywords |
| 130 | + ), ( |
| 131 | + f"Expected to find traces from meaningful keywords {meaningful_keywords}, " |
| 132 | + f"but traces were: {post_tracing_log_matches[:10]}..." |
| 133 | + ) |
0 commit comments