bad-logs.txt

// This is a BAD run!
...
stap_start_task_finder:1680: utrace attaching pid 9666
__stp_utrace_attach:539: utrace_attach_task returned success
__stp_utrace_attach:541: utrace_set_events returned 0
stap_start_task_finder:1686: utrace attach returned 0
stap_start_task_finder:1763: path equal: [/home/agentzh/a.out] == [/home/agentzh/a.out]
stap_start_task_finder:1779: setting up events for 9666
__stp_utrace_attach:539: utrace_attach_task returned success
__stp_utrace_attach:541: utrace_set_events returned 0
__stp_utrace_attach:563: utrace_control returned -115
stap_start_task_finder:1786: utrace attach returned 0
...
__stp_utrace_attach:541: utrace_set_events returned 0
stap_start_task_finder:1686: utrace attach returned 0
__stp_call_callbacks:599: enter tgt=00000000697c4715 tsk=000000001c4cb7ac pid=9666
stap_start_task_finder:1753: path not equal: [/home/agentzh/a.out] != [/usr/bin/tee]
__stp_call_callbacks:604: pid: 9666
stap_start_task_finder:1680: utrace attaching pid 5576
__stp_call_callbacks:614: calling callback 00000000b23fa590
__stp_utrace_attach:539: utrace_attach_task returned success
__stp_call_callbacks:618: callback returned 0
__stp_utrace_attach:541: utrace_set_events returned 0
stap_start_task_finder:1686: utrace attach returned 0
...

stap.patch

diff --git a/runtime/linux/debug.h b/runtime/linux/debug.h
index e23ee96e7..02921de0d 100644
--- a/runtime/linux/debug.h
+++ b/runtime/linux/debug.h
@@ -73,6 +73,16 @@
 #define dbug_unwind(level, args...) ;
 #endif
 
+
+#ifdef DEBUG_TASK_FINDER
+#define dbug_task(args...) do {                                     \
+		_stp_dbug(__FUNCTION__, __LINE__, args);        \
+	} while (0)
+#else
+#define dbug_task(level, args...) ;
+#endif
+
+
 #if defined(DEBUG_TASK_FINDER_VMA)
 #define dbug_task_vma(level, args...) do {                                     \
                if ((level) <= DEBUG_TASK_FINDER_VMA)                               \
diff --git a/runtime/linux/task_finder2.c b/runtime/linux/task_finder2.c
index 6f5d637da..9619b4bd0 100644
--- a/runtime/linux/task_finder2.c
+++ b/runtime/linux/task_finder2.c
@@ -36,9 +36,9 @@ static atomic_t __stp_attach_count = ATOMIC_INIT (0);
 #define debug_task_finder_attach() (atomic_inc(&__stp_attach_count))
 #define debug_task_finder_detach() (atomic_dec(&__stp_attach_count))
 #define debug_task_finder_report()					\
-    (printk(KERN_ERR "%s:%d - attach count: %d, inuse count: %d\n",	\
-	    __FUNCTION__, __LINE__, atomic_read(&__stp_attach_count),	\
-	    atomic_read(&__stp_inuse_count)))
+    dbug_task("attach count: %d, inuse count: %d\n",	\
+	    atomic_read(&__stp_attach_count),	\
+	    atomic_read(&__stp_inuse_count))
 #else
 #define debug_task_finder_attach()	/* empty */
 #define debug_task_finder_detach()	/* empty */
@@ -248,6 +248,8 @@ stap_register_task_finder_target(struct stap_task_finder_target *new_tgt)
 	else
 		new_tgt->pathlen = 0;
 
+	dbug_task("find target");
+
 	// Make sure everything is initialized properly.
 	new_tgt->engine_attached = 0;
 	new_tgt->mmap_events = 0;
@@ -518,7 +520,9 @@ __stp_utrace_attach(struct task_struct *tsk,
 
 	engine = utrace_attach_task(tsk, UTRACE_ATTACH_CREATE, ops, data);
 	if (IS_ERR(engine)) {
-		int error = -PTR_ERR(engine);
+		int error;
+		dbug_task("utrace_attach_task returned error");
+		error = -PTR_ERR(engine);
 		if (error != ESRCH && error != ENOENT) {
 			_stp_error("utrace_attach returned error %d on pid %d",
 				   error, (int)tsk->pid);
@@ -526,12 +530,15 @@ __stp_utrace_attach(struct task_struct *tsk,
 		}
 	}
 	else if (unlikely(engine == NULL)) {
+		dbug_task("utrace_attach_task returned NULL");
 		_stp_error("utrace_attach returned NULL on pid %d",
 			   (int)tsk->pid);
 		rc = EFAULT;
 	}
 	else {
+		dbug_task("utrace_attach_task returned success");
 		rc = utrace_set_events(tsk, engine, event_flags);
+		dbug_task("utrace_set_events returned %d", rc);
 		if (rc == -EINPROGRESS) {
 			/*
 			 * It's running our callback, so we have to
@@ -553,6 +560,7 @@ __stp_utrace_attach(struct task_struct *tsk,
 
 			if (action != UTRACE_RESUME) {
 				rc = utrace_control(tsk, engine, action);
+				dbug_task("utrace_control returned %d", rc);
 				/* If utrace_control() returns
 				 * EINPROGRESS when we're trying to
 				 * stop/interrupt, that means the task
@@ -588,9 +596,13 @@ __stp_call_callbacks(struct stap_task_finder_target *tgt,
 	struct list_head *cb_node;
 	int rc;
 
+	dbug_task("enter tgt=%p tsk=%p pid=%d", tgt, tsk, tsk ? tsk->tgid : -1);
+
 	if (tgt == NULL || tsk == NULL)
 		return;
 
+	dbug_task("pid: %d", tsk->tgid);
+
 	list_for_each(cb_node, &tgt->callback_list_head) {
 		struct stap_task_finder_target *cb_tgt;
 
@@ -599,7 +611,12 @@ __stp_call_callbacks(struct stap_task_finder_target *tgt,
 		if (cb_tgt == NULL || cb_tgt->callback == NULL)
 			continue;
 
+		dbug_task("calling callback %p", cb_tgt->callback);
+
 		rc = cb_tgt->callback(cb_tgt, tsk, register_p, process_p);
+
+		dbug_task("callback returned %d", rc);
+
 		if (rc != 0) {
 			_stp_warn("task_finder %s%scallback for task %d failed: %d",
                                   (cb_tgt->purpose?:""), (cb_tgt->purpose?" ":""),
@@ -834,8 +851,10 @@ __stp_utrace_attach_match_filename(struct task_struct *tsk,
 			continue;
 		else if (tgt->pathlen > 0
 			 && (tgt->pathlen != filelen
-			     || strcmp(tgt->procname, filename) != 0))
+			     || strcmp(tgt->procname, filename) != 0)) {
+			dbug_task("path NOT equal: [%s] != [%s]", tgt->procname, filename);
 			continue;
+		}
 		/* Ignore pid-based target, they were handled at startup. */
 		else if (tgt->pid != 0)
 			continue;
@@ -854,6 +873,7 @@ __stp_utrace_attach_match_filename(struct task_struct *tsk,
 		}
 #endif
 
+		dbug_task("utrace attach to %d", tsk->tgid);
 
 		// Set up events we need for attached tasks. We won't
 		// actually call the callbacks here - we'll call them
@@ -1657,9 +1677,14 @@ stap_start_task_finder(void)
 		if (_stp_target && tsk->tgid != _stp_target)
 			continue;
 
+		dbug_task("utrace attaching pid %d", tsk->tgid);
+
 		rc = __stp_utrace_attach(tsk, &__stp_utrace_task_finder_ops, 0,
 					 __STP_TASK_FINDER_EVENTS,
 					 UTRACE_RESUME);
+
+		dbug_task("utrace attach returned %d", rc);
+
 		if (rc == EPERM) {
 			/* Ignore EPERM errors, which mean this wasn't
 			 * a thread we can attach to. */
@@ -1724,13 +1749,20 @@ stap_start_task_finder(void)
 			else if (tgt->pathlen > 0
 				 && (tgt->pathlen != mmpathlen
 				     || strcmp(tgt->procname, mmpath) != 0))
+			{
+				dbug_task("path not equal: [%s] != [%s]", tgt->procname, mmpath);
 				continue;
+			}
 			/* pid-based target */
 			else if (tgt->pid != 0 && tgt->pid != tsk->pid)
 				continue;
 			/* Notice that "pid == 0" (which means to
 			 * probe all threads) falls through. */
 
+			if (tgt->pathlen > 0) {
+				dbug_task("path equal: [%s] == [%s]", tgt->procname, mmpath);
+			}
+
 #if ! STP_PRIVILEGE_CONTAINS (STP_PRIVILEGE, STP_PR_STAPDEV) && \
     ! STP_PRIVILEGE_CONTAINS (STP_PRIVILEGE, STP_PR_STAPSYS)
 			/* Make sure unprivileged users only probe their own threads.  */
@@ -1739,14 +1771,20 @@ stap_start_task_finder(void)
 					_stp_warn("Process %d does not belong to unprivileged user %d",
 						  tsk->pid, _stp_uid);
 				}
+				dbug_task("uid != euid: %d != %d", _stp_uid, tsk_euid);
 				continue;
 			}
 #endif
 
+			dbug_task("setting up events for %d", tsk->tgid);
+
 			// Set up events we need for attached tasks.
 			rc = __stp_utrace_attach(tsk, &tgt->ops, tgt,
 						 __STP_ATTACHED_TASK_EVENTS,
 						 UTRACE_STOP);
+
+			dbug_task("utrace attach returned %d", rc);
+
 			if (rc != 0 && rc != EPERM)
 				goto stf_err;
 			rc = 0;		/* ignore EPERM */
@@ -1771,18 +1809,13 @@ stap_task_finder_post_init(void)
 		return;
 	}
 
-#ifdef DEBUG_TASK_FINDER
-	printk(KERN_ERR "%s:%d - entry.\n", __FUNCTION__, __LINE__);
-#endif
+	dbug_task("entry.");
 	rcu_read_lock();
 	do_each_thread(grp, tsk) {
 		struct list_head *tgt_node;
 
 		if (atomic_read(&__stp_task_finder_state) != __STP_TF_RUNNING) {
-#ifdef DEBUG_TASK_FINDER
-			printk(KERN_ERR "%s:%d - exiting early...\n",
-			       __FUNCTION__, __LINE__);
-#endif
+			dbug_task("exiting early...");
 			break;
 		}
 
@@ -1794,6 +1827,8 @@ stap_task_finder_post_init(void)
 		if (tsk->tgid != tsk->pid)
 			continue;
 
+		dbug_task("checking task %d:%d", tsk->pid, tsk->tgid);
+
 		/* See if we need to "poke" this thread. */
 		list_for_each(tgt_node, &__stp_task_finder_list) {
 			struct stap_task_finder_target *tgt;
@@ -1804,14 +1839,19 @@ stap_task_finder_post_init(void)
 			if (tgt == NULL || !tgt->engine_attached)
 				continue;
 
+			dbug_task("attaching to task %d", tsk->tgid);
+
 			// If we found an "interesting" task earlier,
 			// stop it.
 			engine = utrace_attach_task(tsk,
 						    UTRACE_ATTACH_MATCH_OPS,
 						    &tgt->ops, tgt);
 			if (engine != NULL && !IS_ERR(engine)) {
+				int rc;
+				dbug_task("found the target task %d, stopping it...", tsk->tgid);
+
 				/* We found a target task. Stop it. */
-				int rc = utrace_control(tsk, engine,
+				rc = utrace_control(tsk, engine,
 							UTRACE_INTERRUPT);
 				/* If utrace_control() returns
 				 * EINPROGRESS when we're
@@ -1824,6 +1864,9 @@ stap_task_finder_post_init(void)
 					_stp_error("utrace_control returned error %d on pid %d",
 						   rc, (int)tsk->pid);
 				}
+
+				dbug_task("interrupting task returned %d (%d)", rc, -EINPROGRESS);
+
 				utrace_engine_put(engine);
 
 				/* Since we only need to interrupt
@@ -1835,9 +1878,7 @@ stap_task_finder_post_init(void)
 	} while_each_thread(grp, tsk);
 	rcu_read_unlock();
 	atomic_set(&__stp_task_finder_complete, 1);
-#ifdef DEBUG_TASK_FINDER
-	printk(KERN_ERR "%s:%d - exit.\n", __FUNCTION__, __LINE__);
-#endif
+	dbug_task("exit.");
 	return;
 }
 
@@ -1858,7 +1899,7 @@ stap_stop_task_finder(void)
 #ifdef DEBUG_TASK_FINDER
 	int i = 0;
 
-	printk(KERN_ERR "%s:%d - entry\n", __FUNCTION__, __LINE__);
+	dbug_task("entry");
 #endif
 	if (atomic_read(&__stp_task_finder_state) == __STP_TF_UNITIALIZED)
 		return;
@@ -1886,7 +1927,7 @@ stap_stop_task_finder(void)
 	}
 #ifdef DEBUG_TASK_FINDER
 	if (i > 0)
-		printk(KERN_ERR "it took %d polling loops to quit.\n", i);
+		dbug_task("it took %d polling loops to quit.", i);
 #endif
 	debug_task_finder_report();
 
@@ -1903,9 +1944,7 @@ stap_stop_task_finder(void)
 	 * everything. */
 	__stp_tf_free_all_task_work();
 
-#ifdef DEBUG_TASK_FINDER
-	printk(KERN_ERR "%s:%d - exit\n", __FUNCTION__, __LINE__);
-#endif
+	dbug_task("exit");
 }
 
 #endif /* TASK_FINDER2_C */