search

draios / sysdig

Linux system exploration and troubleshooting tool with first class support for containers
http://www.sysdig.com/
Other
7.75k stars 727 forks source link

Syscalls with custom fillers are not "filled" by the kernel module #1468

Open fntlnz opened 5 years ago

fntlnz commented 5 years ago

tl;dr

On kernel 5.1.4-arch1-1-ARCH with sysdig commit from dev 92622e3e2a33d5f0f5b2b84d1abd95211d1e67d8, when using the kernel module, all the syscalls with a filler as defined here do not get the information filled.

When using the BPF probe everything works just fine.

Examples

Here are a couple of examples with fillers:

unlinkat

kernel module, has a custom filler, NOT FILLING

https://github.com/draios/sysdig/blob/fd3dfd1e2e1757173722dfe78485c9302ec037cb/driver/ppm_fillers.c#L2864

sudo ./build/userspace/sysdig/sysdig evt.type=unlinkat -p" %evt.num %evt.outputtime %evt.cpu %proc.name (%thread.tid) %evt.dir %evt.type %evt.info"
 318016 08:44:34.393391409 5 systemd-journal (30231) > unlinkat
 318070 08:44:34.394990332 5 systemd-journal (30231) > unlinkat
 1779662 08:44:39.204469453 3 systemd-journal (30231) > unlinkat
 1779804 08:44:39.216152228 3 systemd-journal (30231) > unlinkat

bpf probe, has a custom filler FILLING https://github.com/draios/sysdig/blob/3b7a794f8d8cf1409a5734a3c6a8ab25daedf110/driver/bpf/fillers.h#L4014

sudo ./build/userspace/sysdig/sysdig -B evt.type=unlinkat -p" %evt.num %evt.outputtime %evt.cpu %proc.name (%thread.tid) %evt.dir %evt.type %evt.info"
 67956 08:47:05.687911623 4 rm (31707) > unlinkat
 67957 08:47:05.687918464 4 rm (31707) < unlinkat res=0 dirfd=-100(AT_FDCWD) name=/tmp/ciao flags=0

connect

kernel module, has a custom filler, NOT FILLING

sudo ./userspace/sysdig/sysdig evt.type=connect -p" %evt.num %evt.outputtime %evt.cpu %proc.name (%thread.tid) %evt.dir %evt.type %evt.info"
o 3543 11:23:39.833130888 0 curl (14903) > connect fd=3(<u>)
 3571 11:23:39.833143730 0 curl (14903) < connect res=-2(ENOENT) tuple=NULL
 3593 11:23:39.833151992 0 curl (14903) > connect fd=3(<u>)
 3600 11:23:39.833154945 0 curl (14903) < connect res=-2(ENOENT) tuple=NULL
 5168 11:23:39.834279755 0 curl (14903) > connect fd=3(<u>)
 5339 11:23:39.834355430 0 curl (14903) < connect res=0 tuple=NULL
 8568 11:23:39.835985334 3 curl (14902) > connect fd=3(<4>)
 8571 11:23:39.836044474 3 curl (14902) < connect res=-115(EINPROGRESS) tuple=NULL

bpf probe, has a custom filler, FILLING

sudo ./userspace/sysdig/sysdig -B evt.type=connect -p" %evt.num %evt.outputtime %evt.cpu %proc.name (%thread.tid) %evt.dir %evt.type %evt.info"
 8748 11:22:44.922928658 1 ping (14867) > connect fd=5(<u>)
 8749 11:22:44.922942074 1 ping (14867) < connect res=-2(ENOENT) tuple=0->ffff9c4f0ef93800 /var/run/nscd/socket
 8754 11:22:44.922954445 1 ping (14867) > connect fd=5(<u>)
 8755 11:22:44.922957975 1 ping (14867) < connect res=-2(ENOENT) tuple=0->ffff9c4f0ef93800 /var/run/nscd/socket
 8958 11:22:44.923791569 1 ping (14867) > connect fd=5(<u>)
 8959 11:22:44.923807116 1 ping (14867) < connect res=0 tuple=ffff9c4f0ef90c00->ffff9c4f0ef93800 /run/dbus/system_bus_socket
 9256 11:22:44.925657185 1 ping (14867) > connect fd=5(<4>)
 9260 11:22:44.925665439 1 ping (14867) < connect res=0 tuple=10.0.2.15:33451->35.184.21.208:1025
 16256 11:22:45.062242810 1 ping (14867) > connect fd=5(<u>)
 16257 11:22:45.062265040 1 ping (14867) < connect res=0 tuple=ffff9c4f0ef91000->ffff9c4f0ef90800 /run/dbus/system_bus_socket
 32954 11:22:47.737778883 2 gpg-agent (14869) > connect fd=9(<u>)
 32955 11:22:47.737792694 2 gpg-agent (14869) < connect res=0 tuple=ffff9c4dfbbd7400->ffff9c4dfbbd4000 /run/user/1000/gnupg/S.gpg-agent
 358235 11:23:29.976117901 5 curl (14881) > connect fd=3(<u>)
 358250 11:23:29.976131671 5 curl (14881) < connect res=-2(ENOENT) tuple=0->ffff9c4d83d80400 /var/run/nscd/socket
 358269 11:23:29.976145189 5 curl (14881) > connect fd=3(<u>)
 358274 11:23:29.976148765 5 curl (14881) < connect res=-2(ENOENT) tuple=0->ffff9c4d83d80400 /var/run/nscd/socket
 359310 11:23:29.977439038 5 curl (14881) > connect fd=3(<u>)
 359328 11:23:29.977454929 5 curl (14881) < connect res=0 tuple=ffff9c4d83d82400->ffff9c4d83d80400 /run/dbus/system_bus_socket
 360845 11:23:29.979137550 0 systemd-resolve (558) > connect fd=19(<4>)
 360846 11:23:29.979145979 0 systemd-resolve (558) < connect res=0 tuple=10.0.2.15:35393->10.0.2.3:53
 361394 11:23:30.003624159 2 curl (14880) > connect fd=3(<4>)
 361395 11:23:30.003744390 2 curl (14880) < connect res=-115(EINPROGRESS) tuple=10.0.2.15:49090->216.58.198.46:80

openat

kernel module, has a custom filler, NOT FILLING

 sudo ./userspace/sysdig/sysdig   evt.type=openat -p" %evt.num %evt.outputtime %evt.cpu %proc.name (%thread.tid) %evt.dir %evt.type %evt.info"
268360 10:55:56.344461465 2 systemd-journal (7424) > openat
 268361 10:55:56.344475449 2 systemd-journal (7424) > openat
 268373 10:55:56.344496813 2 systemd-journal (7424) > openat
 268374 10:55:56.344508898 2 systemd-journal (7424) > openat

bpf probe, has a custom filler, FILLING

 sudo ./userspace/sysdig/sysdig -B  evt.type=openat -p" %evt.num %evt.outputtime %evt.cpu %proc.name (%thread.tid) %evt.dir %evt.type %evt.info"
 392 10:55:13.479026956 5 tmux: (22767) > openat
 393 10:55:13.479044359 5 tmux: (22767) < openat fd=14(<f>/proc/12464/cmdline) dirfd=-100(AT_FDCWD) name=/proc/12464/cmdline flags=1(O_RDONLY) mode=0 dev=4
 1069 10:55:13.986222639 5 tmux: (22767) > openat
 1070 10:55:13.986245020 5 tmux: (22767) < openat fd=14(<f>/proc/12464/cmdline) dirfd=-100(AT_FDCWD) name=/proc/12464/cmdline flags=1(O_RDONLY) mode=0 dev=4
 8111 10:55:14.492291848 5 tmux: (22767) > openat
 8112 10:55:14.492312760 5 tmux: (22767) < openat fd=14(<f>/proc/12464/cmdline) dirfd=-100(AT_FDCWD) name=/proc/12464/cmdline flags=1(O_RDONLY) mode=0 dev=4

Here are a couple of examples without fillers

unlink

kernel module, does not have a custom filler, FILLING

sudo ./userspace/sysdig/sysdig  evt.type=unlink -p" %evt.num %evt.outputtime %evt.cpu %proc.name (%thread.tid) %evt.dir %evt.type %evt.info"
 741603 10:58:40.443888645 1 zsh (12631) > unlink
 741613 10:58:40.443921230 1 zsh (12631) < unlink res=0 path=/home/vagrant/.zsh_history.LOCK

bpf probe, does not have a custom filler, FILLING

sudo ./userspace/sysdig/sysdig -B  evt.type=unlink -p" %evt.num %evt.outputtime %evt.cpu %proc.name (%thread.tid) %evt.dir %evt.type %evt.info"
 61687 10:58:11.927697209 1 zsh (12631) > unlink
 61688 10:58:11.927746678 1 zsh (12631) < unlink res=0 path=/home/vagrant/.zsh_history.LOCK

rmdir

kernel module, does not have a custom filler, FILLING

sudo ./userspace/sysdig/sysdig evt.type=rmdir  -p" %evt.num %evt.outputtime %evt.cpu %proc.name (%thread.tid) %evt.dir %evt.type %evt.info"
 137115 11:27:35.882425149 1 rmdir (15090) > rmdir
 137116 11:27:35.882434286 1 rmdir (15090) < rmdir res=0 path=/tmp/mydir

bpf probe, does not have a custom filler, FILLING

sudo ./userspace/sysdig/sysdig -B evt.type=rmdir  -p" %evt.num %evt.outputtime %evt.cpu %proc.name (%thread.tid) %evt.dir %evt.type %evt.info"
 73486 11:28:02.662688926 3 rmdir (15128) > rmdir
 73487 11:28:02.662698493 3 rmdir (15128) < rmdir res=0 path=/tmp/mydir

Notice how the ones without fillers just work.

More details

kernel version extended

Linux l13o1 5.1.4-arch1-1-ARCH #1 SMP PREEMPT Wed May 22 08:06:56 UTC 2019 x86_64 GNU/Linux
fntlnz commented 5 years ago

Update, just tested this on a machine with an older kernel and works as expected:

sudo ./userspace/sysdig/sysdig  evt.type=unlinkat  -p" %evt.num %evt.outputtime %evt.cpu %proc.name (%thread.tid) %evt.dir %evt.type %evt.info"
 5672 14:29:07.650800968 1 rm (22218) > unlinkat
 5673 14:29:07.650834692 1 rm (22218) < unlinkat res=0 dirfd=-100(AT_FDCWD) name=ciao(/home/ubuntu/sysdig/build/ciao) flags=0

Kernel info

Linux gallifrey 4.15.0-1044-aws #46-Ubuntu SMP Thu Jul 4 13:38:28 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
fntlnz commented 5 years ago

Debugged this a bit, it looks like that ppm_copy_from_user returns 16 while doing __copy_from_user_inatomic by calling raw_copy_from_user

However raw_copy_from_user didn't change between the two reported versions, it actually didn't change in the past two years.

So at this point I have two hypothesis:

fntlnz commented 5 years ago

Update: It happens everytime val_to_ring is called with is_user true.

github-actions[bot] commented 1 year ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.