syscall-logger: log blocked syscalls (#3164)

Previously if a syscall blocked, it wasn't recorded in the strace file
until if and when it ran again and completed. Recording blocked syscalls
is slightly redundant since it logs the syscall and parameters multiple
times, but makes it easier to see why control switched to another
thread, and logs syscalls that blocking and never complete, e.g. because
another thread in the process called `exit_group`, the simulation ended,
or in the (unmerged) implementation of execve, which "blocks" and never
returns.

e.g.

```
00:00:01.000000000 [tid 1000] clone(17, 0x0, 0x0, 0x0, 0x0) = 1001
00:00:01.000000000 [tid 1001] write(4, "*", 1) = 1
00:00:01.000000000 [tid 1001] exit_group(...) = <native>
00:00:01.000000000 [tid 1000] read(3, 0x7fffffffe707, 1) = 1
```

->

```
00:00:01.000000000 [tid 1000] clone(17, 0x0, 0x0, 0x0, 0x0) = 1001
00:00:01.000000000 [tid 1000] read(3, 0x7fffffffe707, 1) = <blocked>
00:00:01.000000000 [tid 1001] write(4, "*", 1) = 1
00:00:01.000000000 [tid 1001] exit_group(...) = <native>
00:00:01.000000000 [tid 1000] read(3, 0x7fffffffe707, 1) = 1
```

src/lib/syscall-logger/src/lib.rs

@@ -196,18 +196,16 @@ pub fn log_syscall(args: TokenStream, input: TokenStream) -> TokenStream {
             // format the result (returns None if the syscall didn't complete)
             let syscall_rv = SyscallResultFmt::<#(#rv_type)*>::new(&rv, #context_arg_name.args.args, strace_fmt_options, &*memory);
 
-            if let Some(ref syscall_rv) = syscall_rv {
-                #context_arg_name.objs.process.with_strace_file(|file| {
-                    write_syscall(
-                        file,
-                        &Worker::current_time().unwrap(),
-                        #context_arg_name.objs.thread.id(),
-                        #syscall_name_str,
-                        &syscall_args,
-                        syscall_rv,
-                    ).unwrap();
-                });
-            }
+            #context_arg_name.objs.process.with_strace_file(|file| {
+                write_syscall(
+                    file,
+                    &Worker::current_time().unwrap(),
+                    #context_arg_name.objs.thread.id(),
+                    #syscall_name_str,
+                    &syscall_args,
+                    syscall_rv,
+                ).unwrap();
+            });
 
             // convert the `SyscallResult` back to the original `Result<T, SyscallError>`
             let rv = if let Some(rv_original_ok) = rv_original_ok {

src/main/host/syscall/formatter.rs

@@ -206,19 +206,13 @@ where
         args: [SysCallReg; 6],
         options: FmtOptions,
         mem: &'a MemoryManager,
-    ) -> Option<Self> {
-        match &rv {
-            SyscallResult::Ok(_)
-            | SyscallResult::Err(SyscallError::Failed(_))
-            | SyscallResult::Err(SyscallError::Native) => Some(Self {
-                rv,
-                args,
-                options,
-                mem,
-                _phantom: PhantomData,
-            }),
-            // the syscall was not completed and will be re-run again later
-            SyscallResult::Err(SyscallError::Blocked(_)) => None,
+    ) -> Self {
+        Self {
+            rv,
+            args,
+            options,
+            mem,
+            _phantom: PhantomData,
         }
     }
 }
@@ -243,8 +237,9 @@ where
             SyscallResult::Err(SyscallError::Native) => {
                 write!(f, "<native>")
             }
-            // the constructor doesn't allow this
-            SyscallResult::Err(SyscallError::Blocked(_)) => unreachable!(),
+            SyscallResult::Err(SyscallError::Blocked(_)) => {
+                write!(f, "<blocked>")
+            }
         }
     }
 }
@@ -303,17 +298,15 @@ mod export {
         let memory = proc.memory_borrow();
         let rv = SyscallResultFmt::<libc::c_long>::new(&result, *args, logging_mode, &memory);
 
-        if let Some(ref rv) = rv {
-            proc.with_strace_file(|file| {
-                let time = Worker::current_time();
+        proc.with_strace_file(|file| {
+            let time = Worker::current_time();
 
-                if let (Some(time), Ok(tid)) = (time, tid.try_into()) {
-                    write_syscall(file, &time, tid, name, args_str, rv).unwrap();
-                } else {
-                    log::warn!("Could not log syscall {name} with time {time:?} and tid {tid}");
-                }
-            });
-        }
+            if let (Some(time), Ok(tid)) = (time, tid.try_into()) {
+                write_syscall(file, &time, tid, name, args_str, rv).unwrap();
+            } else {
+                log::warn!("Could not log syscall {name} with time {time:?} and tid {tid}");
+            }
+        });
 
         // need to return the result, otherwise the drop impl will free the condition pointer
         result.into()