Skip to content

Add option to log syscalls#1886

Merged
stevenengler merged 9 commits intoshadow:mainfrom
stevenengler:log-syscalls
Feb 7, 2022
Merged

Add option to log syscalls#1886
stevenengler merged 9 commits intoshadow:mainfrom
stevenengler:log-syscalls

Conversation

@stevenengler
Copy link
Copy Markdown
Contributor

@stevenengler stevenengler commented Feb 3, 2022 •
edited
Loading

Adds the experimental "use_strace_logging" option to log syscalls. The syscalls are logged to hosts/hostname/hostname.procname.pid.strace files (one for each process). The goals are:

  1. strace-inspired formatting of arguments/values
  2. easy to log syscalls without much per-syscall boilerplate

The first goal is achieved using an abuse of generics, and the second goal is achieved using a proc macro.

For example, to add logging for a Rust syscall, annotate it with the log_syscall macro.

#[log_syscall(/* rv */ libc::ssize_t, /* fd */ libc::c_int, /* buf */ *const libc::c_void,
              /* count */ libc::size_t)]
pub fn read(ctx: &mut ThreadContext, args: &SysCallArgs) -> SyscallResult { ... }

#[log_syscall(/* rv */ libc::c_int, /* oldfd */ libc::c_int, /* newfd */ libc::c_int,
              /* flags */ nix::fcntl::OFlag)]
pub fn dup3(ctx: &mut ThreadContext, args: &SysCallArgs) -> SyscallResult { ... }

Example of the strace file output for tor:

00:01:00.000 pipe2([-1, -1] (0x5555558d0448), O_CLOEXEC | O_NDELAY | O_NONBLOCK) = 0
00:07:56.000 socket(Inet, 526337, 6) = 20
00:07:56.000 write(1, "Jan 01 00:07:56.000 [notice] Circuit han"..., 89) = 89
00:07:56.000 write(1, "Jan 01 00:07:56.000 [notice] Since start"..., 261) = 261
00:07:56.000 write(1, "Jan 01 00:07:56.000 [notice] Heartbeat: "..., 250) = 250
00:07:56.000 epoll_ctl(...) = 0
00:07:56.100 epoll_wait(...) = 1
00:07:56.100 getsockopt(...) = 0
00:07:56.100 sendto(20, "GET /tor/status-vote/current/consensus/B"..., 266, (empty), 0x0, 0) = 266
00:07:56.100 epoll_ctl(...) = 0
00:07:56.200 epoll_wait(...) = 1
00:07:56.200 recvfrom(20, 0x55555597b30c, 7968, (empty), 0x0, 0x0) = 1167
00:07:56.301 epoll_wait(...) = 1
00:07:56.301 read(16, 0x5555559a5913, 5) = 5
00:07:56.301 read(16, 0x5555559a5918, 4065) = 1429
00:07:56.301 read(16, 0x5555559a5ead, 2636) = -11 (EAGAIN: Try again)
00:07:56.301 close(20) = 0
00:07:56.301 rename(...) = <native>
00:07:56.301 madvise(...) = <native>
00:07:56.301 connect(...) = -115 (EINPROGRESS: Operation now in progress)

Limitations:

  • syscall handlers implemented in C only show ... for arguments
  • syscalls handled entirely by the shim won't be logged
  • there is a performance penalty when using it, which is why it's off by default
  • the return values for native syscalls won't be logged

@stevenengler stevenengler self-assigned this Feb 3, 2022
@github-actions github-actions bot added Component: Build Build/install tools and dependencies Component: Libraries Support functions like LD_PRELOAD and logging Component: Main Composing the core Shadow executable Component: Testing Unit and integration tests and frameworks labels Feb 3, 2022
@github-actions github-actions bot added the Component: Documentation In-repository documentation, under docs/ label Feb 3, 2022
sporksmith
sporksmith approved these changes Feb 3, 2022
View reviewed changes
Copy link
Copy Markdown
Contributor

@sporksmith sporksmith left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Very cool!

src/main/host/syscall/format.rs

// implement display formatting

simple_display_impl!(i8, i16, i32, i64, isize);
Copy link
Copy Markdown
Contributor

@sporksmith sporksmith Feb 3, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we could reduce the macro usage here while keeping the boilerplate low with an extra layer of Traits. IMO this would make the code easier to read and debug, though maybe I just need to get more comfortable with Rust macros :).

I think it'd go something like:

trait SimpleSyscallDataDisplay : Display {};

impl SyscallDataDisplay for SimpleSyscallDataDisplay {
    fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
        write!(f, "{}", self)
    }
};

impl SimpleSyscallDataDisplay for i8;
impl SimpleSyscallDataDisplay for i16;
impl SimpleSyscallDataDisplay for i32;
...

Copy link
Copy Markdown
Contributor Author

@stevenengler stevenengler Feb 7, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't know of a way to do this with traits.

If you use impl SyscallDataDisplay for dyn SimpleSyscallDataDisplay {...}, then impl SimpleSyscallDataDisplay for i8 won't implement SyscallDataDisplay for i8 since i8 is not a trait object: https://play.rust-lang.org/?version=stable&mode=debug&edition=2021&gist=143bd80d7e99d949dacb88fc06a90253

If you use impl<T> SyscallDataDisplay for T where T: SimpleSyscallDataDisplay {...} and impl<T> SyscallDataDisplay for T where T: SimpleSyscallDataDebug {...}, then you get conflicting trait implementations: https://play.rust-lang.org/?version=stable&mode=debug&edition=2021&gist=2478d50fdd6e8b3cf5ab0e7235e4732c

Copy link
Copy Markdown
Contributor Author

@stevenengler stevenengler Feb 7, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'll merge now, and then if there's a better way to do it I can make a new PR later.

@stevenengler stevenengler merged commit ba0ab5d into shadow:main Feb 7, 2022
@stevenengler stevenengler deleted the log-syscalls branch February 7, 2022 16:59
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@sporksmith sporksmith sporksmith approved these changes

Assignees

@stevenengler stevenengler

Labels

Component: Build Build/install tools and dependencies Component: Documentation In-repository documentation, under docs/ Component: Libraries Support functions like LD_PRELOAD and logging Component: Main Composing the core Shadow executable Component: Testing Unit and integration tests and frameworks

Projects

None yet

Milestone

Improve design of logging and output ...

Development

Successfully merging this pull request may close these issues.

2 participants

@stevenengler @sporksmith