Generate trace logs in wiggle albeit behind a feature gate

This commit augments `wiggle` with trace log generation for the shims,
returned errno values, and returned values proper (if any, i.e.,
different than unit type `()`). What that means is that every syscall
will have auto-generated up to 3 traces, for instance,

```
 TRACE wasi_common::wasi::wasi_snapshot_preview1 > fd_prestat_get(fd=Fd(3))
 TRACE wasi_common::wasi::wasi_snapshot_preview1 >      | result=(buf=Dir(PrestatDir { pr_name_len: 1 }))
 TRACE wasi_common::wasi::wasi_snapshot_preview1 >      | errno=No error occurred. System call completed successfully. (Errno::Success(0))
```

Putting logging behind a feature gate in this case means that the log calls
are generated by the `wiggle` crate regardless if the client requested
the feature or not, however, then their usage in the client lib is
dictated by the presence of the feature flag. So, for instance, `wasi-common`
has this feature enabled by default, while any other client lib
using `wiggle` if they don't want tracing enabled, they will just
leave the feature off. I'm not sure if this is what we wanted
but seemed easiest to implement quickly. Lemme y'all know your thoughts
about this!

crates/wasi-common/Cargo.toml

@@ -36,6 +36,11 @@ cpu-time = "1.0"
 maintenance = { status = "actively-developed" }
 
 [features]
+default = ["trace_log"]
+# This feature enables `log::trace` calls in syscalls shims, in effect
+# emulating something like `strace`. This feature is an opt-out and hence
+# enabled by default.
+trace_log = []
 # Need to make the wiggle_metadata feature available to consumers of this
 # crate if they want the snapshots to have metadata available.
 wiggle_metadata = ["wiggle/wiggle_metadata"]

crates/wasi-common/src/entry.rs

@@ -115,9 +115,9 @@ impl EntryRights {
 
 impl fmt::Display for EntryRights {
     fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
-        writeln!(
+        write!(
             f,
-            "EntryRights {{\n\tbase: {},\n\tinheriting: {}\n}}",
+            "EntryRights {{ base: {}, inheriting: {} }}",
             self.base, self.inheriting
         )
     }

crates/wasi-common/src/snapshots/wasi_snapshot_preview1.rs

@@ -16,8 +16,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         argv: &GuestPtr<'b, GuestPtr<'b, u8>>,
         argv_buf: &GuestPtr<'b, u8>,
     ) -> Result<()> {
-        trace!("args_get(argv_ptr={:?}, argv_buf={:?})", argv, argv_buf);
-
         let mut argv = argv.clone();
         let mut argv_buf = argv_buf.clone();
 
@@ -34,18 +32,12 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
     }
 
     fn args_sizes_get(&self) -> Result<(types::Size, types::Size)> {
-        trace!("args_sizes_get");
-
         let argc = self.args.len().try_into()?;
         let mut argv_size: types::Size = 0;
         for arg in &self.args {
             let arg_len = arg.as_bytes_with_nul().len().try_into()?;
             argv_size = argv_size.checked_add(arg_len).ok_or(Errno::Overflow)?;
         }
-
-        trace!("     | *argc_ptr={:?}", argc);
-        trace!("     | *argv_buf_size_ptr={:?}", argv_size);
-
         Ok((argc, argv_size))
     }
 
@@ -54,12 +46,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         environ: &GuestPtr<'b, GuestPtr<'b, u8>>,
         environ_buf: &GuestPtr<'b, u8>,
     ) -> Result<()> {
-        trace!(
-            "environ_get(environ={:?}, environ_buf={:?})",
-            environ,
-            environ_buf
-        );
-
         let mut environ = environ.clone();
         let mut environ_buf = environ_buf.clone();
 
@@ -76,36 +62,26 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
     }
 
     fn environ_sizes_get(&self) -> Result<(types::Size, types::Size)> {
-        trace!("environ_sizes_get");
-
         let environ_count = self.env.len().try_into()?;
         let mut environ_size: types::Size = 0;
         for environ in &self.env {
             let env_len = environ.as_bytes_with_nul().len().try_into()?;
             environ_size = environ_size.checked_add(env_len).ok_or(Errno::Overflow)?;
         }
-
-        trace!("     | *environ_count_ptr={:?}", environ_count);
-        trace!("     | *environ_size_ptr={:?}", environ_size);
-
         Ok((environ_count, environ_size))
     }
 
     fn clock_res_get(&self, id: types::Clockid) -> Result<types::Timestamp> {
-        trace!("clock_res_get(id={:?})", id);
         let resolution = clock::res_get(id)?;
-        trace!("     | *resolution_ptr={:?}", resolution);
         Ok(resolution)
     }
 
     fn clock_time_get(
         &self,
         id: types::Clockid,
-        precision: types::Timestamp,
+        _precision: types::Timestamp,
     ) -> Result<types::Timestamp> {
-        trace!("clock_time_get(id={:?}, precision={:?})", id, precision);
         let time = clock::time_get(id)?;
-        trace!("     | *time_ptr={:?}", time);
         Ok(time)
     }
 
@@ -116,13 +92,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         len: types::Filesize,
         advice: types::Advice,
     ) -> Result<()> {
-        trace!(
-            "fd_advise(fd={:?}, offset={}, len={}, advice={})",
-            fd,
-            offset,
-            len,
-            advice
-        );
         let required_rights = EntryRights::from_base(types::Rights::FD_ADVISE);
         let entry = self.get_entry(fd)?;
         let desc = entry.as_descriptor(&required_rights)?;
@@ -140,8 +109,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         offset: types::Filesize,
         len: types::Filesize,
     ) -> Result<()> {
-        trace!("fd_allocate(fd={:?}, offset={}, len={})", fd, offset, len);
-
         let required_rights = EntryRights::from_base(types::Rights::FD_ALLOCATE);
         let entry = self.get_entry(fd)?;
         let desc = entry.as_descriptor(&required_rights)?;
@@ -165,22 +132,17 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
     }
 
     fn fd_close(&self, fd: types::Fd) -> Result<()> {
-        trace!("fd_close(fd={:?})", fd);
-
         if let Ok(fe) = self.get_entry(fd) {
             // can't close preopened files
             if fe.preopen_path.is_some() {
                 return Err(Errno::Notsup);
             }
         }
-
         self.remove_entry(fd)?;
         Ok(())
     }
 
     fn fd_datasync(&self, fd: types::Fd) -> Result<()> {
-        trace!("fd_datasync(fd={:?})", fd);
-
         let required_rights = EntryRights::from_base(types::Rights::FD_DATASYNC);
         let entry = self.get_entry(fd)?;
         let file = entry.as_descriptor(&required_rights)?;
@@ -193,8 +155,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
     }
 
     fn fd_fdstat_get(&self, fd: types::Fd) -> Result<types::Fdstat> {
-        trace!("fd_fdstat_get(fd={:?})", fd);
-
         let fe = self.get_entry(fd)?;
         let wasi_file = fe.as_descriptor(&EntryRights::empty())?;
         let fs_flags = match &*wasi_file.borrow() {
@@ -209,15 +169,10 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             fs_rights_inheriting: rights.inheriting,
             fs_flags,
         };
-
-        trace!("     | *buf={:?}", fdstat);
-
         Ok(fdstat)
     }
 
     fn fd_fdstat_set_flags(&self, fd: types::Fd, flags: types::Fdflags) -> Result<()> {
-        trace!("fd_fdstat_set_flags(fd={:?}, fdflags={})", fd, flags);
-
         let required_rights = EntryRights::from_base(types::Rights::FD_FDSTAT_SET_FLAGS);
         let entry = self.get_entry(fd)?;
         let desc = entry.as_descriptor(&required_rights)?;
@@ -245,12 +200,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         fs_rights_base: types::Rights,
         fs_rights_inheriting: types::Rights,
     ) -> Result<()> {
-        trace!(
-            "fd_fdstat_set_rights(fd={:?}, fs_rights_base={}, fs_rights_inheriting={})",
-            fd,
-            fs_rights_base,
-            fs_rights_inheriting
-        );
         let rights = EntryRights::new(fs_rights_base, fs_rights_inheriting);
         let entry = self.get_entry(fd)?;
         if !entry.rights.get().contains(&rights) {
@@ -261,8 +210,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
     }
 
     fn fd_filestat_get(&self, fd: types::Fd) -> Result<types::Filestat> {
-        trace!("fd_filestat_get(fd={:?})", fd);
-
         let required_rights = EntryRights::from_base(types::Rights::FD_FILESTAT_GET);
         let entry = self.get_entry(fd)?;
         let desc = entry.as_descriptor(&required_rights)?;
@@ -271,15 +218,10 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             Descriptor::VirtualFile(virt) => virt.filestat_get()?,
             _ => return Err(Errno::Badf),
         };
-
-        trace!("     | *filestat_ptr={:?}", host_filestat);
-
         Ok(host_filestat)
     }
 
     fn fd_filestat_set_size(&self, fd: types::Fd, size: types::Filesize) -> Result<()> {
-        trace!("fd_filestat_set_size(fd={:?}, size={})", fd, size);
-
         let required_rights = EntryRights::from_base(types::Rights::FD_FILESTAT_SET_SIZE);
         let entry = self.get_entry(fd)?;
         let desc = entry.as_descriptor(&required_rights)?;
@@ -302,13 +244,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         mtim: types::Timestamp,
         fst_flags: types::Fstflags,
     ) -> Result<()> {
-        trace!(
-            "fd_filestat_set_times(fd={:?}, atim={}, mtim={}, fst_flags={})",
-            fd,
-            atim,
-            mtim,
-            fst_flags
-        );
         let required_rights = EntryRights::from_base(types::Rights::FD_FILESTAT_SET_TIMES);
         let entry = self.get_entry(fd)?;
         let desc = entry.as_descriptor(&required_rights)?;
@@ -322,8 +257,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         iovs: &types::IovecArray<'_>,
         offset: types::Filesize,
     ) -> Result<types::Size> {
-        trace!("fd_pread(fd={:?}, iovs={:?}, offset={})", fd, iovs, offset,);
-
         let mut buf = Vec::new();
         let mut bc = GuestBorrows::new();
         bc.borrow_slice(iovs)?;
@@ -360,15 +293,10 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             _ => return Err(Errno::Badf),
         };
         let host_nread = host_nread.try_into()?;
-
-        trace!("     | *nread={:?}", host_nread);
-
         Ok(host_nread)
     }
 
     fn fd_prestat_get(&self, fd: types::Fd) -> Result<types::Prestat> {
-        trace!("fd_prestat_get(fd={:?})", fd);
-
         // TODO: should we validate any rights here?
         let fe = self.get_entry(fd)?;
         let po_path = fe.preopen_path.as_ref().ok_or(Errno::Notsup)?;
@@ -389,13 +317,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         path: &GuestPtr<u8>,
         path_len: types::Size,
     ) -> Result<()> {
-        trace!(
-            "fd_prestat_dir_name(fd={:?}, path={:?}, path_len={})",
-            fd,
-            path,
-            path_len
-        );
-
         // TODO: should we validate any rights here?
         let fe = self.get_entry(fd)?;
         let po_path = fe.preopen_path.as_ref().ok_or(Errno::Notsup)?;
@@ -410,7 +331,7 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             return Err(Errno::Nametoolong);
         }
 
-        trace!("     | (path_ptr,path_len)='{}'", host_path);
+        trace!("     | path='{}'", host_path);
 
         path.as_array(host_path_len)
             .copy_from_slice(host_path.as_bytes())?;
@@ -424,13 +345,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         ciovs: &types::CiovecArray<'_>,
         offset: types::Filesize,
     ) -> Result<types::Size> {
-        trace!(
-            "fd_pwrite(fd={:?}, ciovs={:?}, offset={})",
-            fd,
-            ciovs,
-            offset,
-        );
-
         let mut buf = Vec::new();
         let mut bc = GuestBorrows::new();
         bc.borrow_slice(ciovs)?;
@@ -466,15 +380,12 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             Descriptor::VirtualFile(virt) => virt.pwritev(&buf, offset)?,
             _ => return Err(Errno::Badf),
         };
-        trace!("     | *nwritten={:?}", host_nwritten);
         let host_nwritten = host_nwritten.try_into()?;
 
         Ok(host_nwritten)
     }
 
     fn fd_read(&self, fd: types::Fd, iovs: &types::IovecArray<'_>) -> Result<types::Size> {
-        trace!("fd_read(fd={:?}, iovs={:?})", fd, iovs);
-
         let mut bc = GuestBorrows::new();
         let mut slices = Vec::new();
         bc.borrow_slice(&iovs)?;
@@ -499,8 +410,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         };
         let host_nread = host_nread.try_into()?;
 
-        trace!("     | *nread={:?}", host_nread);
-
         Ok(host_nread)
     }
 
@@ -511,14 +420,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         buf_len: types::Size,
         cookie: types::Dircookie,
     ) -> Result<types::Size> {
-        trace!(
-            "fd_readdir(fd={:?}, buf={:?}, buf_len={}, cookie={:?})",
-            fd,
-            buf,
-            buf_len,
-            cookie,
-        );
-
         let required_rights = EntryRights::from_base(types::Rights::FD_READDIR);
         let entry = self.get_entry(fd)?;
         let desc = entry.as_descriptor(&required_rights)?;
@@ -555,14 +456,10 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             _ => return Err(Errno::Badf),
         };
 
-        trace!("     | *buf_used={:?}", bufused);
-
         Ok(bufused)
     }
 
     fn fd_renumber(&self, from: types::Fd, to: types::Fd) -> Result<()> {
-        trace!("fd_renumber(from={:?}, to={:?})", from, to);
-
         if !self.contains_entry(from) {
             return Err(Errno::Badf);
         }
@@ -591,13 +488,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         offset: types::Filedelta,
         whence: types::Whence,
     ) -> Result<types::Filesize> {
-        trace!(
-            "fd_seek(fd={:?}, offset={:?}, whence={:?})",
-            fd,
-            offset,
-            whence,
-        );
-
         let base = if offset == 0 && whence == types::Whence::Cur {
             types::Rights::FD_TELL
         } else {
@@ -617,14 +507,10 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             _ => return Err(Errno::Badf),
         };
 
-        trace!("     | *newoffset={:?}", host_newoffset);
-
         Ok(host_newoffset)
     }
 
     fn fd_sync(&self, fd: types::Fd) -> Result<()> {
-        trace!("fd_sync(fd={:?})", fd);
-
         let required_rights = EntryRights::from_base(types::Rights::FD_SYNC);
         let entry = self.get_entry(fd)?;
         let desc = entry.as_descriptor(&required_rights)?;
@@ -637,8 +523,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
     }
 
     fn fd_tell(&self, fd: types::Fd) -> Result<types::Filesize> {
-        trace!("fd_tell(fd={:?})", fd);
-
         let required_rights = EntryRights::from_base(types::Rights::FD_TELL);
         let entry = self.get_entry(fd)?;
         let desc = entry.as_descriptor(&required_rights)?;
@@ -648,14 +532,10 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             _ => return Err(Errno::Badf),
         };
 
-        trace!("     | *newoffset={:?}", host_offset);
-
         Ok(host_offset)
     }
 
     fn fd_write(&self, fd: types::Fd, ciovs: &types::CiovecArray<'_>) -> Result<types::Size> {
-        trace!("fd_write(fd={:?}, ciovs={:#x?})", fd, ciovs);
-
         let mut bc = GuestBorrows::new();
         let mut slices = Vec::new();
         bc.borrow_slice(&ciovs)?;
@@ -711,13 +591,10 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
                 SandboxedTTYWriter::new(&mut io::stderr()).write_vectored(&slices)?
             }
         };
-        trace!("     | *nwritten={:?}", host_nwritten);
         Ok(host_nwritten.try_into()?)
     }
 
     fn path_create_directory(&self, dirfd: types::Fd, path: &GuestPtr<'_, str>) -> Result<()> {
-        trace!("path_create_directory(dirfd={:?}, path={:?})", dirfd, path);
-
         let required_rights =
             EntryRights::from_base(types::Rights::PATH_OPEN | types::Rights::PATH_CREATE_DIRECTORY);
         let entry = self.get_entry(dirfd)?;
@@ -737,13 +614,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         flags: types::Lookupflags,
         path: &GuestPtr<'_, str>,
     ) -> Result<types::Filestat> {
-        trace!(
-            "path_filestat_get(dirfd={:?}, flags={:?}, path={:?})",
-            dirfd,
-            flags,
-            path,
-        );
-
         let required_rights = EntryRights::from_base(types::Rights::PATH_FILESTAT_GET);
         let entry = self.get_entry(dirfd)?;
         let resolved = path::get(&entry, &required_rights, flags, path, false)?;
@@ -760,8 +630,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             _ => path::filestat_get(resolved, flags)?,
         };
 
-        trace!("     | *filestat_ptr={:?}", host_filestat);
-
         Ok(host_filestat)
     }
 
@@ -774,16 +642,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         mtim: types::Timestamp,
         fst_flags: types::Fstflags,
     ) -> Result<()> {
-        trace!(
-            "path_filestat_set_times(dirfd={:?}, flags={:?}, path={:?}, atim={}, mtim={}, fst_flags={})",
-            dirfd,
-            flags,
-            path,
-            atim,
-            mtim,
-            fst_flags,
-        );
-
         let required_rights = EntryRights::from_base(types::Rights::PATH_FILESTAT_SET_TIMES);
         let entry = self.get_entry(dirfd)?;
         let resolved = path::get(&entry, &required_rights, flags, path, false)?;
@@ -803,15 +661,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         new_fd: types::Fd,
         new_path: &GuestPtr<'_, str>,
     ) -> Result<()> {
-        trace!(
-            "path_link(old_fd={:?}, old_flags={:?}, old_path={:?}, new_fd={:?}, new_path={:?})",
-            old_fd,
-            old_flags,
-            old_path,
-            new_fd,
-            new_path,
-        );
-
         let required_rights = EntryRights::from_base(types::Rights::PATH_LINK_SOURCE);
         let old_entry = self.get_entry(old_fd)?;
         let resolved_old = path::get(
@@ -847,24 +696,13 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         fs_rights_inheriting: types::Rights,
         fdflags: types::Fdflags,
     ) -> Result<types::Fd> {
-        trace!(
-            "path_open(dirfd={:?}, dirflags={}, path={:?}, oflags={}, fs_rights_base={}, fs_rights_inheriting={}, fdflags={}",
-            dirfd,
-            dirflags,
-            path,
-            oflags,
-            fs_rights_base,
-            fs_rights_inheriting,
-            fdflags,
-        );
-
         let needed_rights = path::open_rights(
             &EntryRights::new(fs_rights_base, fs_rights_inheriting),
             oflags,
             fdflags,
         );
 
-        trace!("     | needed rights = {}", needed_rights);
+        trace!("     | needed_rights={}", needed_rights);
 
         let resolved = {
             let entry = self.get_entry(dirfd)?;
@@ -902,9 +740,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         rights.inheriting &= fs_rights_inheriting;
         fe.rights.set(rights);
         let guest_fd = self.insert_entry(fe)?;
-
-        trace!("     | *fd={:?}", guest_fd);
-
         Ok(guest_fd)
     }
 
@@ -915,14 +750,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         buf: &GuestPtr<u8>,
         buf_len: types::Size,
     ) -> Result<types::Size> {
-        trace!(
-            "path_readlink(dirfd={:?}, path={:?}, buf={:?}, buf_len={})",
-            dirfd,
-            path,
-            buf,
-            buf_len,
-        );
-
         let required_rights = EntryRights::from_base(types::Rights::PATH_READLINK);
         let entry = self.get_entry(dirfd)?;
         let resolved = path::get(
@@ -946,16 +773,10 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             _ => path::readlink(resolved, slice)?,
         };
         let host_bufused = host_bufused.try_into()?;
-
-        trace!("     | (buf_ptr,*buf_used)={:?}", slice);
-        trace!("     | *buf_used={:?}", host_bufused);
-
         Ok(host_bufused)
     }
 
     fn path_remove_directory(&self, dirfd: types::Fd, path: &GuestPtr<'_, str>) -> Result<()> {
-        trace!("path_remove_directory(dirfd={:?}, path={:?})", dirfd, path);
-
         let required_rights = EntryRights::from_base(types::Rights::PATH_REMOVE_DIRECTORY);
         let entry = self.get_entry(dirfd)?;
         let resolved = path::get(
@@ -981,14 +802,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         new_fd: types::Fd,
         new_path: &GuestPtr<'_, str>,
     ) -> Result<()> {
-        trace!(
-            "path_rename(old_fd={:?}, old_path={:?}, new_fd={:?}, new_path={:?})",
-            old_fd,
-            old_path,
-            new_fd,
-            new_path,
-        );
-
         let required_rights = EntryRights::from_base(types::Rights::PATH_RENAME_SOURCE);
         let entry = self.get_entry(old_fd)?;
         let resolved_old = path::get(
@@ -1008,8 +821,8 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             true,
         )?;
 
-        log::debug!("path_rename resolved_old={:?}", resolved_old);
+        debug!("path_rename resolved_old={:?}", resolved_old);
-        log::debug!("path_rename resolved_new={:?}", resolved_new);
+        debug!("path_rename resolved_new={:?}", resolved_new);
 
         if let (Descriptor::OsHandle(_), Descriptor::OsHandle(_)) =
             (resolved_old.dirfd(), resolved_new.dirfd())
@@ -1028,13 +841,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         dirfd: types::Fd,
         new_path: &GuestPtr<'_, str>,
     ) -> Result<()> {
-        trace!(
-            "path_symlink(old_path={:?}, dirfd={:?}, new_path={:?})",
-            old_path,
-            dirfd,
-            new_path,
-        );
-
         let required_rights = EntryRights::from_base(types::Rights::PATH_SYMLINK);
         let entry = self.get_entry(dirfd)?;
         let resolved_new = path::get(
@@ -1051,7 +857,7 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             &*raw
         };
 
-        trace!("     | (old_path_ptr,old_path_len)='{}'", old_path);
+        trace!("     | old_path='{}'", old_path);
 
         match resolved_new.dirfd() {
             Descriptor::VirtualFile(_virt) => {
@@ -1062,8 +868,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
     }
 
     fn path_unlink_file(&self, dirfd: types::Fd, path: &GuestPtr<'_, str>) -> Result<()> {
-        trace!("path_unlink_file(dirfd={:?}, path={:?})", dirfd, path);
-
         let required_rights = EntryRights::from_base(types::Rights::PATH_UNLINK_FILE);
         let entry = self.get_entry(dirfd)?;
         let resolved = path::get(
@@ -1085,13 +889,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
         out: &GuestPtr<types::Event>,
         nsubscriptions: types::Size,
     ) -> Result<types::Size> {
-        trace!(
-            "poll_oneoff(in_={:?}, out={:?}, nsubscriptions={})",
-            in_,
-            out,
-            nsubscriptions,
-        );
-
         if u64::from(nsubscriptions) > types::Filesize::max_value() {
             return Err(Errno::Inval);
         }
@@ -1120,8 +917,8 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             match subscription.u {
                 types::SubscriptionU::Clock(clock) => {
                     let delay = clock::to_relative_ns_delay(&clock)?;
-                    log::debug!("poll_oneoff event.u.clock = {:?}", clock);
+                    debug!("poll_oneoff event.u.clock = {:?}", clock);
-                    log::debug!("poll_oneoff delay = {:?}ns", delay);
+                    debug!("poll_oneoff delay = {:?}ns", delay);
                     let current = poll::ClockEventData {
                         delay,
                         userdata: subscription.userdata,
@@ -1185,9 +982,9 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
                 }
             }
         }
-        log::debug!("poll_oneoff events = {:?}", events);
+        debug!("poll_oneoff events = {:?}", events);
-        log::debug!("poll_oneoff timeout = {:?}", timeout);
+        debug!("poll_oneoff timeout = {:?}", timeout);
-        log::debug!("poll_oneoff fd_events = {:?}", fd_events);
+        debug!("poll_oneoff fd_events = {:?}", fd_events);
         // The underlying implementation should successfully and immediately return
         // if no events have been passed. Such situation may occur if all provided
         // events have been filtered out as errors in the code above.
@@ -1200,9 +997,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
             let event_ptr = event_ptr?;
             event_ptr.write(event)?;
         }
-
-        trace!("     | *nevents={:?}", nevents);
-
         Ok(nevents)
     }
 
@@ -1210,7 +1004,6 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
     // in the CI. Once we figure out non-returns in `wiggle`, this should be gone.
     #[allow(unreachable_code)]
     fn proc_exit(&self, rval: types::Exitcode) -> std::result::Result<(), ()> {
-        trace!("proc_exit(rval={:?})", rval);
         // TODO: Rather than call std::process::exit here, we should trigger a
         // stack unwind similar to a trap.
         std::process::exit(rval as i32);
@@ -1221,14 +1014,11 @@ impl<'a> WasiSnapshotPreview1 for WasiCtx {
     }
 
     fn sched_yield(&self) -> Result<()> {
-        trace!("sched_yield()");
         std::thread::yield_now();
         Ok(())
     }
 
     fn random_get(&self, buf: &GuestPtr<u8>, buf_len: types::Size) -> Result<()> {
-        trace!("random_get(buf={:?}, buf_len={:?})", buf, buf_len);
-
         let slice = unsafe {
             let mut bc = GuestBorrows::new();
             let buf = buf.as_array(buf_len);

crates/wiggle/generate/src/funcs.rs

@@ -38,9 +38,17 @@ pub fn define_func(names: &Names, func: &witx::InterfaceFunc) -> TokenStream {
     };
 
     let err_type = coretype.ret.map(|ret| ret.param.tref);
-    let err_val = err_type
+    let ret_err = err_type
         .clone()
-        .map(|_res| quote!(#abi_ret::from(e)))
+        .map(|_res| {
+            quote! {
+                #[cfg(feature = "trace_log")]
+                {
+                    log::trace!("     | errno={}", e);
+                }
+                return #abi_ret::from(e);
+            }
+        })
         .unwrap_or_else(|| quote!(()));
 
     let error_handling = |location: &str| -> TokenStream {
@@ -78,13 +86,39 @@ pub fn define_func(names: &Names, func: &witx::InterfaceFunc) -> TokenStream {
     let (trait_rets, trait_bindings) = if func.results.len() < 2 {
         (quote!({}), quote!(_))
     } else {
-        let trait_rets = func
+        let trait_rets: Vec<_> = func
             .results
             .iter()
             .skip(1)
-            .map(|result| names.func_param(&result.name));
+            .map(|result| names.func_param(&result.name))
-        let tuple = quote!((#(#trait_rets),*));
+            .collect();
-        (tuple.clone(), tuple)
+        let bindings = quote!((#(#trait_rets),*));
+        let names: Vec<_> = func
+            .results
+            .iter()
+            .skip(1)
+            .map(|result| {
+                let name = names.func_param(&result.name);
+                let fmt = match &*result.tref.type_() {
+                    witx::Type::Builtin(_)
+                    | witx::Type::Enum(_)
+                    | witx::Type::Flags(_)
+                    | witx::Type::Handle(_)
+                    | witx::Type::Int(_) => "{}",
+                    _ => "{:?}",
+                };
+                format!("{}={}", name.to_string(), fmt)
+            })
+            .collect();
+        let trace_fmt = format!("     | result=({})", names.join(","));
+        let rets = quote! {
+            #[cfg(feature = "trace_log")]
+            {
+                log::trace!(#trace_fmt, #(#trait_rets),*);
+            }
+            (#(#trait_rets),*)
+        };
+        (rets, bindings)
     };
 
     // Return value pointers need to be validated before the api call, then
@@ -101,18 +135,40 @@ pub fn define_func(names: &Names, func: &witx::InterfaceFunc) -> TokenStream {
         let err_typename = names.type_ref(&err_type, anon_lifetime());
         quote! {
             let success:#err_typename = wiggle::GuestErrorType::success();
+            #[cfg(feature = "trace_log")]
+            {
+                log::trace!("     | errno={}", success);
+            }
             #abi_ret::from(success)
         }
     } else {
         quote!()
     };
 
+    let (placeholders, args): (Vec<_>, Vec<_>) = func
+        .params
+        .iter()
+        .map(|param| {
+            let name = names.func_param(&param.name);
+            let fmt = if passed_by_reference(&*param.tref.type_()) {
+                "{:?}"
+            } else {
+                "{}"
+            };
+            (format!("{}={}", name.to_string(), fmt), quote!(#name))
+        })
+        .unzip();
+    let trace_fmt = format!("{}({})", ident.to_string(), placeholders.join(","));
     quote!(pub fn #ident(#abi_args) -> #abi_ret {
         #(#marshal_args)*
         #(#marshal_rets_pre)*
+        #[cfg(feature = "trace_log")]
+        {
+            log::trace!(#trace_fmt, #(#args),*);
+        }
         let #trait_bindings  = match ctx.#ident(#(#trait_args),*) {
-            Ok(#trait_bindings) => #trait_rets,
+            Ok(#trait_bindings) => { #trait_rets },
-            Err(e) => { return #err_val; },
+            Err(e) => { #ret_err },
         };
         #(#marshal_rets_post)*
         #success