Add logging to help figure out CI failures

Author: gnurizen

.github/workflows/unit-test-on-pull-request.yml

@@ -246,6 +246,8 @@ jobs:
         kernel:
           - 5.10.217  # Pre-6.6, uses single-shot mode
           - 6.8.10    # Post-6.6, supports multi-uprobe
+          - 6.12.16
+          - 6.16
     steps:
       - name: Clone code
         uses: actions/checkout@v4

interpreter/rtld/rtld.go

@@ -28,20 +28,23 @@ type instance struct {
 // Loader detects if the ELF file contains the dlopen symbol in its dynamic symbol table
 func Loader(ebpf interpreter.EbpfHandler, info *interpreter.LoaderInfo) (interpreter.Data, error) {
 	fileName := info.FileName()
+	log.Infof("[dlopen] Loader called for file: %s", fileName)
 
 	ef, err := info.GetELF()
 	if err != nil {
+		log.Debugf("[dlopen] Failed to get ELF for %s: %v", fileName, err)
 		return nil, err
 	}
 
 	// Look for the dlopen symbol in the dynamic symbol table
 	sym, err := ef.LookupSymbol("dlopen")
 	if err != nil || sym == nil {
 		// No dlopen symbol found, this library doesn't support dynamic loading
+		log.Debugf("[dlopen] No dlopen symbol found in %s", fileName)
 		return nil, nil
 	}
 
-	log.Debugf("Found dlopen symbol in %s at 0x%x", fileName, sym.Address)
+	log.Infof("[dlopen] Found dlopen symbol in %s at 0x%x", fileName, sym.Address)
 
 	return &data{
 		path:    fileName,
@@ -52,13 +55,16 @@ func Loader(ebpf interpreter.EbpfHandler, info *interpreter.LoaderInfo) (interpr
 // Attach attaches the uprobe to the dlopen function
 func (d *data) Attach(ebpf interpreter.EbpfHandler, pid libpf.PID, bias libpf.Address,
 	_ remotememory.RemoteMemory) (interpreter.Instance, error) {
+	log.Infof("[dlopen] Attempting to attach uprobe for PID %d on %s at 0x%x", pid, d.path, d.address)
+
 	// Attach uprobe to dlopen using the address stored during Loader
 	lc, err := ebpf.AttachUprobe(pid, d.path, d.address, "uprobe_dlopen")
 	if err != nil {
+		log.Errorf("[dlopen] Failed to attach uprobe to dlopen for PID %d: %v", pid, err)
 		return nil, fmt.Errorf("failed to attach uprobe to dlopen: %w", err)
 	}
 
-	log.Debugf("[dlopen] Attached uprobe to dlopen for PID %d on %s at 0x%x",
+	log.Infof("[dlopen] Successfully attached uprobe to dlopen for PID %d on %s at 0x%x",
 		pid, d.path, d.address)
 
 	d.lc = lc

interpreter/rtld/rtld_test.go

@@ -80,11 +80,31 @@ func TestIntegrationSingleShot(t *testing.T) {
 		t.Skip("This test requires root privileges")
 	}
 
+	// Enable info logging to see uprobe attachment
+	log.SetLevel(log.InfoLevel)
+
 	// Enable debug logging for CI debugging
 	if os.Getenv("DEBUG_TEST") != "" {
 		log.SetLevel(log.DebugLevel)
 	}
 
+	t.Logf("Test process PID: %d", os.Getpid())
+
+	// Check which libraries are available and contain dlopen
+	t.Logf("Checking for dlopen-containing libraries...")
+	possibleLibs := []string{
+		"/lib/x86_64-linux-gnu/libc.so.6",
+		"/lib64/libc.so.6",
+		"/usr/lib/x86_64-linux-gnu/libc.so.6",
+		"/lib/x86_64-linux-gnu/ld-linux-x86-64.so.2",
+		"/lib64/ld-linux-x86-64.so.2",
+	}
+	for _, lib := range possibleLibs {
+		if _, err := os.Stat(lib); err == nil {
+			t.Logf("Found library: %s", lib)
+		}
+	}
+
 	// Override HasMultiUprobeSupport to force single-shot mode
 	multiUProbeOverride := false
 	util.SetTestOnlyMultiUprobeSupport(&multiUProbeOverride)
@@ -95,10 +115,12 @@ func TestIntegrationSingleShot(t *testing.T) {
 	defer cancel()
 
 	// Start the tracer with all tracers enabled
+	t.Logf("Starting tracer...")
 	traceCh, trc := testutils.StartTracer(ctx, t,
 		tracertypes.AllTracers(),
 		false)
 	defer trc.Close()
+	t.Logf("Tracer started successfully")
 
 	// Consume traces to prevent blocking
 	go func() {
@@ -117,23 +139,32 @@ func TestIntegrationSingleShot(t *testing.T) {
 	require.Eventually(t, func() bool {
 		// Get the initial metric value
 		initialCount := getEBPFMetricValue(trc, metrics.IDDlopenUprobeHits)
-		//t.Logf("Initial dlopen uprobe metric count: %d", initialCount)
+		t.Logf("Initial dlopen uprobe metric count: %d", initialCount)
 
 		// Use dlopen to load a shared library
 		// libm is a standard math library that's always present
 		lib, err := dlopen.GetHandle([]string{
 			"/lib/x86_64-linux-gnu/libm.so.6",
 			"libm.so.6",
 		})
-		require.NoError(t, err, "Failed to open libm.so.6")
+		if err != nil {
+			t.Logf("Failed to open libm.so.6: %v", err)
+			require.NoError(t, err, "Failed to open libm.so.6")
+		}
+		t.Logf("Successfully opened libm.so.6")
 		defer lib.Close()
 
 		// Get the metrics after dlopen
 		finalCount := getEBPFMetricValue(trc, metrics.IDDlopenUprobeHits)
-		//t.Logf("Final dlopen uprobe metric count: %d", finalCount)
+		t.Logf("Final dlopen uprobe metric count: %d (delta: %d)", finalCount, finalCount-initialCount)
 
 		// Check that the metric was incremented
-		return finalCount > initialCount
+		if finalCount > initialCount {
+			t.Logf("SUCCESS: Metric incremented from %d to %d", initialCount, finalCount)
+			return true
+		}
+		t.Logf("Metric not incremented yet, retrying...")
+		return false
 	}, 10*time.Second, 50*time.Millisecond)
 }
 
@@ -142,21 +173,29 @@ func getEBPFMetricValue(trc *tracer.Tracer, metricID metrics.MetricID) uint64 {
 	ebpfMaps := trc.GetEbpfMaps()
 	metricsMap, ok := ebpfMaps["metrics"]
 	if !ok {
+		log.Debugf("Metrics map not found in eBPF maps")
 		return 0
 	}
 
 	// Find the eBPF metric ID that corresponds to our metrics.MetricID
 	var ebpfMetricID uint32
+	found := false
 	for ebpfID, id := range support.MetricsTranslation {
 		if id == metricID {
 			ebpfMetricID = uint32(ebpfID)
+			found = true
 			break
 		}
 	}
+	if !found {
+		log.Debugf("Metric ID %v not found in MetricsTranslation", metricID)
+		return 0
+	}
 
 	// Read the per-CPU values
 	var perCPUValues []uint64
 	if err := metricsMap.Lookup(unsafe.Pointer(&ebpfMetricID), &perCPUValues); err != nil {
+		log.Debugf("Failed to lookup metric %v (eBPF ID %d): %v", metricID, ebpfMetricID, err)
 		return 0
 	}
 
@@ -165,5 +204,6 @@ func getEBPFMetricValue(trc *tracer.Tracer, metricID metrics.MetricID) uint64 {
 	for _, val := range perCPUValues {
 		total += val
 	}
+	log.Debugf("Metric %v (eBPF ID %d): total=%d from %d CPUs", metricID, ebpfMetricID, total, len(perCPUValues))
 	return total
 }