1919
2020from __future__ import annotations
2121
22+ import logging
2223import os
2324import signal
2425import subprocess
3940 analyze_events ,
4041)
4142
43+ logger = logging .getLogger (__name__ )
44+
4245
4346# ---------------------------------------------------------------------------
4447# Constants
@@ -184,7 +187,7 @@ def kill_stale_qemu_instances() -> None:
184187 try :
185188 old_pid = int (pid_file .read_text ().strip ())
186189 os .kill (old_pid , signal .SIGTERM )
187- print (f"Killed stale QEMU instance { instance_id } (PID { old_pid } )" )
190+ logger . info (f"Killed stale QEMU instance { instance_id } (PID { old_pid } )" )
188191 time .sleep (1 )
189192 pid_file .unlink (missing_ok = True )
190193 except (ProcessLookupError , ValueError ):
@@ -277,49 +280,48 @@ def start_qemu2_services(host: str) -> None:
277280
278281def verify_sd_match (ip : str , expected : SDExpectation , actual : SDResult ) -> None :
279282 """Verify SD offers/finds/subscriptions match expected values."""
280- print ("-" * 80 )
281- print (f"CHECKING: { expected .name } ({ ip } )" )
282- print ("-" * 80 )
283+ logger . info ("-" * 80 )
284+ logger . info (f"CHECKING: { expected .name } ({ ip } )" )
285+ logger . info ("-" * 80 )
283286
284287 for field in ("offers" , "finds" , "subscribed" ):
285288 exp_val = getattr (expected , field )
286289 act_val = getattr (actual , field )
287290 label = "SUBSCRIBED SUCCESSFULLY TO" if field == "subscribed" else field .upper ()
288- print (f" { label } :" )
289- print (f" expected: { sorted (exp_val )} " )
290- print (f" actual: { sorted (act_val )} " )
291+ logger . info (f" { label } :" )
292+ logger . info (f" expected: { sorted (exp_val )} " )
293+ logger . info (f" actual: { sorted (act_val )} " )
291294 assert exp_val == act_val , f"[{ expected .name } ] { label } mismatch"
292- print (" -> OK" )
295+ logger . info (" -> OK" )
293296
294297
295298def verify_partial_sd (ip : str , parsed : dict [str , SDResult ], output : str ) -> None :
296299 """Verify partial SD behavior (offers/finds present, no subscriptions)."""
297300 assert ip in parsed , f"No SOME/IP-SD data for { ip } .\n Output:\n { output } "
298301 actual = parsed [ip ]
299302
300- print (f" OFFERS: { sorted (actual .offers )} " )
303+ logger . info (f" OFFERS: { sorted (actual .offers )} " )
301304 assert actual .offers , f"Should have offers, got: { actual .offers } "
302- print (" -> OK (has offers)" )
305+ logger . info (" -> OK (has offers)" )
303306
304- print (f" FINDS: { sorted (actual .finds )} " )
307+ logger . info (f" FINDS: { sorted (actual .finds )} " )
305308 assert actual .finds , f"Should have finds, got: { actual .finds } "
306- print (" -> OK (has finds)" )
309+ logger . info (" -> OK (has finds)" )
307310
308- print (f" SUBSCRIBED: { sorted (actual .subscribed )} " )
311+ logger . info (f" SUBSCRIBED: { sorted (actual .subscribed )} " )
309312 assert not actual .subscribed , (
310313 f"Should have no subscriptions, got: { actual .subscribed } "
311314 )
312- print (" -> OK (no subscriptions as expected)" )
315+ logger . info (" -> OK (no subscriptions as expected)" )
313316
314317
315318def verify_event_match (
316319 ip : str , expected : EventExpectation , events : dict [str , list [dict ]]
317320) -> None :
318321 """Verify SOME/IP event notification matches expected event_id and payload_size."""
319- print ()
320- print ("-" * 80 )
321- print (f"CHECKING: { expected .name } ({ ip } )" )
322- print ("-" * 80 )
322+ logger .info ("-" * 80 )
323+ logger .info (f"CHECKING: { expected .name } ({ ip } )" )
324+ logger .info ("-" * 80 )
323325
324326 matching = [e for e in events .get (ip , []) if e ["service_id" ] == expected .service_id ]
325327 assert matching , (
@@ -332,21 +334,21 @@ def verify_event_match(
332334 payload_size = matching [0 ]["payload_size" ],
333335 )
334336
335- print (
337+ logger . info (
336338 f" event_id: expected=0x{ expected .event_id :04x} actual=0x{ actual .event_id :04x} "
337339 )
338340 assert actual .event_id == expected .event_id , (
339341 f"[{ expected .name } ] event_id mismatch: expected 0x{ expected .event_id :04x} , got 0x{ actual .event_id :04x} "
340342 )
341- print (" -> OK" )
343+ logger . info (" -> OK" )
342344
343- print (
345+ logger . info (
344346 f" payload_size: expected={ expected .payload_size } B actual={ actual .payload_size } B"
345347 )
346348 assert actual .payload_size == expected .payload_size , (
347349 f"[{ expected .name } ] payload_size mismatch: expected { expected .payload_size } , got { actual .payload_size } "
348350 )
349- print (" -> OK" )
351+ logger . info (" -> OK" )
350352
351353
352354class TestSomeIPSD :
@@ -396,7 +398,7 @@ def test_negative_no_qemu_only_tcpdump(self):
396398
397399 parsed = analyze_pcap (pcap )
398400 assert not parsed , f"Expected no SD data, found: { list (parsed .keys ())} "
399- print ("PASS: No SOME/IP-SD traffic when no QEMU instances running" )
401+ logger . info ("PASS: No SOME/IP-SD traffic when no QEMU instances running" )
400402
401403 def test_negative_both_qemus_no_services (self , qemu_ifs_image , qemu_run_script ):
402404 """Negative: Both QEMUs running but no services - no traffic expected."""
@@ -407,8 +409,8 @@ def test_negative_both_qemus_no_services(self, qemu_ifs_image, qemu_run_script):
407409 instance1 = start_qemu (qemu_ifs_image , qemu_run_script , instance_id = 1 )
408410 instance2 = start_qemu (qemu_ifs_image , qemu_run_script , instance_id = 2 )
409411 try :
410- print (f"QEMU 1: { instance1 .ssh_host } , QEMU 2: { instance2 .ssh_host } " )
411- print ("Waiting 5 seconds without starting services..." )
412+ logger . info (f"QEMU 1: { instance1 .ssh_host } , QEMU 2: { instance2 .ssh_host } " )
413+ logger . info ("Waiting 5 seconds without starting services..." )
412414
413415 with tcpdump_capture (pcap , tmp / "tcpdump_no_services.log" ):
414416 time .sleep (5 )
@@ -418,7 +420,7 @@ def test_negative_both_qemus_no_services(self, qemu_ifs_image, qemu_run_script):
418420
419421 parsed = analyze_pcap (pcap )
420422 assert not parsed , f"Expected no SD data, found: { list (parsed .keys ())} "
421- print ("PASS: No SOME/IP-SD traffic when QEMUs running without services" )
423+ logger . info ("PASS: No SOME/IP-SD traffic when QEMUs running without services" )
422424
423425 def test_negative_only_qemu1_with_services (self , qemu_ifs_image , qemu_run_script ):
424426 """Negative: Only QEMU 1 with services - offers/finds but no subscriptions."""
@@ -430,23 +432,23 @@ def test_negative_only_qemu1_with_services(self, qemu_ifs_image, qemu_run_script
430432 instance = start_qemu (qemu_ifs_image , qemu_run_script , instance_id = 1 )
431433 try :
432434 with tcpdump_capture (pcap , log ):
433- print (f"Starting services on QEMU 1 ({ instance .ssh_host } )..." )
435+ logger . info (f"Starting services on QEMU 1 ({ instance .ssh_host } )..." )
434436 start_qemu1_services (instance .ssh_host )
435- print (f"Waiting { SERVICE_SETTLE_TIME } s for SD exchanges..." )
437+ logger . info (f"Waiting { SERVICE_SETTLE_TIME } s for SD exchanges..." )
436438 time .sleep (SERVICE_SETTLE_TIME )
437439 finally :
438440 instance .stop ()
439441
440442 parsed = analyze_pcap (pcap )
441443
442- print ("-" * 80 )
443- print ("CHECKING: Only QEMU 1 running with services" )
444- print ("-" * 80 )
444+ logger . info ("-" * 80 )
445+ logger . info ("CHECKING: Only QEMU 1 running with services" )
446+ logger . info ("-" * 80 )
445447
446448 verify_partial_sd (QEMU1_IP , parsed , str (pcap ))
447449 assert QEMU2_IP not in parsed , "QEMU 2 should not be present"
448- print (" QEMU 2: Not present (as expected)" )
449- print ("PASS: Only QEMU 1 - offers/finds present, no subscriptions" )
450+ logger . info (" QEMU 2: Not present (as expected)" )
451+ logger . info ("PASS: Only QEMU 1 - offers/finds present, no subscriptions" )
450452
451453 def test_negative_only_qemu2_with_services (self , qemu_ifs_image , qemu_run_script ):
452454 """Negative: Only QEMU 2 with services - offers/finds but no subscriptions."""
@@ -458,23 +460,23 @@ def test_negative_only_qemu2_with_services(self, qemu_ifs_image, qemu_run_script
458460 instance = start_qemu (qemu_ifs_image , qemu_run_script , instance_id = 2 )
459461 try :
460462 with tcpdump_capture (pcap , log ):
461- print (f"Starting sample_client on QEMU 2 ({ instance .ssh_host } )..." )
463+ logger . info (f"Starting sample_client on QEMU 2 ({ instance .ssh_host } )..." )
462464 start_qemu2_services (instance .ssh_host )
463- print (f"Waiting { SERVICE_SETTLE_TIME } s for SD exchanges..." )
465+ logger . info (f"Waiting { SERVICE_SETTLE_TIME } s for SD exchanges..." )
464466 time .sleep (SERVICE_SETTLE_TIME )
465467 finally :
466468 instance .stop ()
467469
468470 parsed = analyze_pcap (pcap )
469471
470- print ("-" * 80 )
471- print ("CHECKING: Only QEMU 2 running with services" )
472- print ("-" * 80 )
472+ logger . info ("-" * 80 )
473+ logger . info ("CHECKING: Only QEMU 2 running with services" )
474+ logger . info ("-" * 80 )
473475
474476 verify_partial_sd (QEMU2_IP , parsed , str (pcap ))
475477 assert QEMU1_IP not in parsed , "QEMU 1 should not be present"
476- print (" QEMU 1: Not present (as expected)" )
477- print ("PASS: Only QEMU 2 - offers/finds present, no subscriptions" )
478+ logger . info (" QEMU 1: Not present (as expected)" )
479+ logger . info ("PASS: Only QEMU 2 - offers/finds present, no subscriptions" )
478480
479481 def test_someip_event_data_transfer (self , qemu_ifs_image , qemu_run_script ):
480482 """Verify SOME/IP event data flows between QEMU 1 and QEMU 2."""
0 commit comments