Merged PR 783872: Add extra logging to BxlObserver::relative_to_absolute

- Debugging some ptrace failures on 1JS
- Also disables report cache on fork/clone calls to fix a unit test that failed due to missed reports.

Related work items: #2171844

Public/Src/Engine/Processes/SandboxedProcessUnix.cs

@@ -1193,7 +1193,7 @@ namespace BuildXL.Processes
                 // We will kill these manually if the pip is exiting
                 Timeout.InfiniteTimeSpan,
                 // The runner will only log to stderr if there's a problem, other logs go to the main log using the fifo
-                errorBuilder: line => { if (line != null) { Logger.Log.PTraceRunnerError(m_loggingContext, line); } },
+                errorBuilder: line => { if (line != null) { Logger.Log.PTraceRunnerError(m_loggingContext, m_reports.PipDescription, line); } },
                 forceAddExecutionPermission: forceAddExecutionPermission
            );
 

Public/Src/Engine/Processes/Tracing/Log.cs

@@ -1265,8 +1265,8 @@ namespace BuildXL.Processes.Tracing
             EventLevel = Level.Error,
             Keywords = (int)Keywords.UserMessage,
             EventTask = (ushort)Tasks.Scheduler,
-            Message = "PTraceRunner logged the following error: {content}")]
-        internal abstract void PTraceRunnerError(LoggingContext loggingContext, string content);
+            Message = "[{pipDescription}] PTraceRunner logged the following error: {content}")]
+        internal abstract void PTraceRunnerError(LoggingContext loggingContext, string pipDescription, string content);
 
         [GeneratedEvent(
             (ushort)LogEventId.ReportArgsMismatch,

Public/Src/Sandbox/Linux/PTraceSandbox.cpp

@@ -551,7 +551,7 @@ void PTraceSandbox::ReportCreate(std::string syscallName, int dirfd, const char
         /* event_type */    ES_EVENT_TYPE_NOTIFY_CREATE,
         /* pid */           m_traceePid,
         /* error */         returnValue,
-        /* src_path */      m_bxl->normalize_path_at(dirfd, pathname, /* oflags */ 0, m_traceePid).c_str());
+        /* src_path */      m_bxl->normalize_path_at(dirfd, pathname, /* oflags */ 0, m_traceePid, syscallName.c_str()).c_str());
     event.SetMode(mode);
     
     m_bxl->CreateAndReportAccess(syscallName.c_str(), event, /* check_cache */ false);
@@ -606,7 +606,7 @@ HANDLER_FUNCTION(execveat)
     int flags = ReadArgumentLong(5);
 
     int oflags = (flags & AT_SYMLINK_NOFOLLOW) ? O_NOFOLLOW : 0;
-    std::string exePath = m_bxl->normalize_path_at(dirfd, pathname.c_str(), oflags, m_traceePid);
+    std::string exePath = m_bxl->normalize_path_at(dirfd, pathname.c_str(), oflags, m_traceePid, SYSCALL_NAME_STRING(execveat));
 
     UpdateTraceeTableForExec(exePath);
 
@@ -735,7 +735,7 @@ HANDLER_FUNCTION(openat)
 {
     auto dirfd = ReadArgumentLong(1);
     auto pathName = ReadArgumentString(SYSCALL_NAME_STRING(openat), 2, /* nullTerminated */ true);
-    auto path = m_bxl->normalize_path_at(dirfd, pathName.c_str(), /* oflags */ 0, m_traceePid);
+    auto path = m_bxl->normalize_path_at(dirfd, pathName.c_str(), /* oflags */ 0, m_traceePid, SYSCALL_NAME_STRING(openat));
     auto flags = ReadArgumentLong(3);
     ReportOpen(path, flags, SYSCALL_NAME_STRING(openat));
 }
@@ -854,8 +854,8 @@ HANDLER_FUNCTION(renameat2)
 
 void PTraceSandbox::HandleRenameGeneric(const char *syscall, int olddirfd, const char *oldpath, int newdirfd, const char *newpath)
 {
-    string oldStr = m_bxl->normalize_path_at(olddirfd, oldpath, O_NOFOLLOW, m_traceePid);
-    string newStr = m_bxl->normalize_path_at(newdirfd, newpath, O_NOFOLLOW, m_traceePid);
+    string oldStr = m_bxl->normalize_path_at(olddirfd, oldpath, O_NOFOLLOW, m_traceePid, syscall);
+    string newStr = m_bxl->normalize_path_at(newdirfd, newpath, O_NOFOLLOW, m_traceePid, syscall);
 
     mode_t mode = m_bxl->get_mode(oldStr.c_str());    
     std::vector<std::string> filesAndDirectories;
@@ -925,8 +925,8 @@ HANDLER_FUNCTION(linkat)
         /* event_type */    ES_EVENT_TYPE_NOTIFY_LINK,
         /* pid */           m_traceePid,
         /* error */         0,
-        /* src_path */      m_bxl->normalize_path_at(olddirfd, oldpath.c_str(), O_NOFOLLOW, m_traceePid).c_str(),
-        /* dest_path */     m_bxl->normalize_path_at(newdirfd, newpath.c_str(), O_NOFOLLOW, m_traceePid).c_str());
+        /* src_path */      m_bxl->normalize_path_at(olddirfd, oldpath.c_str(), O_NOFOLLOW, m_traceePid, SYSCALL_NAME_STRING(linkat)).c_str(),
+        /* dest_path */     m_bxl->normalize_path_at(newdirfd, newpath.c_str(), O_NOFOLLOW, m_traceePid, SYSCALL_NAME_STRING(linkat)).c_str());
 
     m_bxl->CreateAndReportAccess(SYSCALL_NAME_STRING(linkat), event);
 }
@@ -1237,7 +1237,7 @@ HANDLER_FUNCTION(name_to_handle_at)
     auto flags = ReadArgumentLong(5);
 
     int oflags = (flags & AT_SYMLINK_FOLLOW) ? 0 : O_NOFOLLOW;
-    string pathStr = m_bxl->normalize_path_at(dirfd, pathname.c_str(), oflags, m_traceePid);
+    string pathStr = m_bxl->normalize_path_at(dirfd, pathname.c_str(), oflags, m_traceePid, SYSCALL_NAME_STRING(name_to_handle_at));
     ReportOpen(pathStr, oflags, SYSCALL_NAME_STRING(name_to_handle_at));
 }
 

Public/Src/Sandbox/Linux/bxl_observer.cpp

@@ -1073,7 +1073,7 @@ void BxlObserver::report_intermediate_symlinks(const char *pathname, pid_t assoc
     resolve_path(fullPath, /* followFinalSymlink */ true, associatedPid);
 }
 
-std::string BxlObserver::normalize_path_at(int dirfd, const char *pathname, int oflags, pid_t associatedPid)
+std::string BxlObserver::normalize_path_at(int dirfd, const char *pathname, int oflags, pid_t associatedPid, const char *systemcall)
 {
     // Observe that dirfd is assumed to point to a directory file descriptor. Under that assumption, it is safe to call fd_to_path for it.
     // TODO: If we wanted to be very defensive, we could also consider the case of some tool invoking any of the *at(... dirfd ...) family with a 
@@ -1087,7 +1087,7 @@ std::string BxlObserver::normalize_path_at(int dirfd, const char *pathname, int
     }
 
     char fullPath[PATH_MAX] = {0};
-    relative_to_absolute(pathname, dirfd, associatedPid, fullPath);    
+    relative_to_absolute(pathname, dirfd, associatedPid, fullPath, systemcall);    
 
     bool followFinalSymlink = (oflags & O_NOFOLLOW) == 0;
     resolve_path(fullPath, followFinalSymlink, associatedPid);
@@ -1095,7 +1095,7 @@ std::string BxlObserver::normalize_path_at(int dirfd, const char *pathname, int
     return fullPath;
 }
 
-void BxlObserver::relative_to_absolute(const char *pathname, int dirfd, int associatedPid, char *fullpath)
+void BxlObserver::relative_to_absolute(const char *pathname, int dirfd, int associatedPid, char *fullpath, const char *systemcall)
 {
     size_t len = 0;
 
@@ -1119,7 +1119,7 @@ void BxlObserver::relative_to_absolute(const char *pathname, int dirfd, int asso
 
         if (len <= 0)
         {
-            _fatal("Could not get path for fd %d; errno: %d", dirfd, errno);
+            _fatal("['%s'] Could not get path for fd %d with path '%s'; errno: %d", systemcall, dirfd, pathname, errno);
         }
 
         fullpath[len] = '/';

Public/Src/Sandbox/Linux/bxl_observer.hpp

@@ -284,7 +284,7 @@ private:
         return str.str();
     }
 
-    void relative_to_absolute(const char *pathname, int dirfd, int associatedPid, char *fullPath);
+    void relative_to_absolute(const char *pathname, int dirfd, int associatedPid, char *fullPath, const char *systemcall = "");
     void resolve_path(char *fullpath, bool followFinalSymlink, pid_t associatedPid);
     
     /**
@@ -409,7 +409,7 @@ public:
     // table properly for the case of pipes when we miss a close.
     std::string fd_to_path(int fd, pid_t associatedPid = 0);
     
-    std::string normalize_path_at(int dirfd, const char *pathname, int oflags = 0, pid_t associatedPid = 0);
+    std::string normalize_path_at(int dirfd, const char *pathname, int oflags = 0, pid_t associatedPid = 0, const char *systemcall = "");
 
     // Whether the given descriptor is a non-file (e.g., a pipe, or socket, etc.)
     static bool is_non_file(const mode_t mode);

Public/Src/Sandbox/Linux/detours.cpp

@@ -170,7 +170,7 @@ static void report_child_process(const char *syscall, BxlObserver *bxl, pid_t ch
 {
     string exePath(bxl->GetProgramPath());
     auto event = buildxl::linux::SandboxEvent::ForkSandboxEvent(parentPid, childPid, exePath);
-    bxl->CreateAndReportAccess(syscall, event);
+    bxl->CreateAndReportAccess(syscall, event, /* check_cache */ false);
 }
 
 static void HandleForkOrCloneReporting(const char *syscall, BxlObserver *bxl, pid_t forkOrCloneChildPidResult)
@@ -1883,7 +1883,7 @@ void __attribute__ ((constructor)) _bxl_linux_sandbox_init(void)
         /* error */         0,
         /* src_path */      BxlObserver::GetInstance()->GetProgramPath());
     
-    BxlObserver::GetInstance()->CreateAndReportAccess("__init__", event);
+    BxlObserver::GetInstance()->CreateAndReportAccess("__init__", event, /* check_cache */ false);
     BxlObserver::GetInstance()->report_exec_args(getpid());
 }