• z

    Zander Mackie

    11 months ago
    @alessandrogario I’ve been seeing this too. Giving some information:
    [STD-DEV]15:26:53 root@si-i-0fe66e9061a89d90d /home/zmackie # uname -a
    Linux si-i-0fe66e9061a89d90d 5.4.0-1054-aws #57~18.04.1-Ubuntu SMP Thu Jul 15 03:21:36 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux
    [STD-DEV]15:26:55 root@si-i-0fe66e9061a89d90d /home/zmackie # cat /etc/issue
    Ubuntu 18.04.5 LTS \n \l
    With
    --verbose
  • a

    alessandrogario

    11 months ago
    I'll create a PR with the fix I was talking about
  • Would it be possible to test it on your system? I used kernel 4.19 on Debian Stretch to replicate the problem, and switching from In to Out alleviated the issue
  • I believe newer kernels will have better handling of page faults
  • Some things can't be switched from In to Out though (like execve, execveat for example, because when we exit the system call the mapped memory will change)
  • z

    Zander Mackie

    11 months ago
    I can test it yes.
  • a

    alessandrogario

    11 months ago
  • z

    Zander Mackie

    11 months ago
    Ah great. Will test out today.
  • a

    alessandrogario

    11 months ago
    Thanks! This should at least improve the situation 🙂
  • z

    Zander Mackie

    11 months ago
    I0908 16:45:09.437614 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall fork (20)
    I0908 16:45:09.442298 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall vfork (28)
    I0908 16:45:09.447696 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall clone (36)
    I0908 16:45:09.451020 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall close (44)
    I0908 16:45:09.454308 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall dup (50)
    I0908 16:45:09.457621 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall dup2 (56)
    I0908 16:45:09.460983 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall dup3 (62)
    I0908 16:45:09.471495 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall creat (71)
    I0908 16:45:09.475664 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall mknod (77)
    I0908 16:45:09.479838 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall mknodat (83)
    I0908 16:45:09.490257 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall open (91)
    I0908 16:45:09.494812 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall openat (97)
    I0908 16:45:09.494910 25867 bpfeventpublisher.cpp:243] Failed to load the BPF probe for syscall openat2: Failed to open the tracepoint descriptor file: /sys/kernel/debug/tracing/events/syscalls/sys_enter_openat2/id. This syscall may not be available on this system, continuing despite the error
    I0908 16:45:09.504556 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall socket (105)
    I0908 16:45:09.507974 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall fcntl (111)
    I0908 16:45:09.512300 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall connect (117)
    I0908 16:45:09.516983 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall accept (123)
    I0908 16:45:09.521683 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall accept4 (129)
    I0908 16:45:09.525904 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall bind (135)
    I0908 16:45:09.529222 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall listen (141)
    I0908 16:45:09.539371 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall chdir (149)
    I0908 16:45:09.542677 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall fchdir (155)
    I0908 16:45:09.547883 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall name_to_handle_at (161)
    I0908 16:45:09.551900 25867 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall open_by_handle_at (167)
    I0908 16:45:09.674875 25867 bpfeventpublisher.cpp:243] Failed to load the BPF probe for syscall execve: The 'enter' program could not be loaded: The program could not be loaded: 0: (bf) r8 = r1
  • Then there was a bunch of what looks like bpf ouput:
    I0908 16:45:09.674875 25867 bpfeventpublisher.cpp:243] Failed to load the BPF probe for syscall execve: The 'enter' program could not be loaded: The program could not be loaded: 0: (bf) r8 = r1
    1: (85) call bpf_get_current_pid_tgid#14
    2: (77) r0 >>= 32
    3: (55) if r0 != 0x650b goto pc+2
     R0_w=inv25867 R8_w=ctx(id=0,off=0,imm=0) R10=fp0
    4: (b7) r0 = 0
    5: (95) exit
    
    from 3 to 6: R0_w=inv(id=0,umax_value=4294967295,var_off=(0x0; 0xffffffff)) R8_w=ctx(id=0,off=0,imm=0) R10=fp0
    6: (b7) r7 = 0
    7: (63) *(u32 *)(r10 -172) = r7
    last_idx 7 first_idx 0
    regs=80 stack=0 before 6: (b7) r7 = 0
    8: (18) r1 = 0xffff901d8f2eae00
    10: (bf) r2 = r10
    11: (07) r2 += -172
    12: (85) call bpf_map_lookup_elem#1
    13: (bf) r6 = r0
    14: (55) if r6 != 0x0 goto pc+2
     R0=inv0 R6_w=inv0 R7=invP0 R8=ctx(id=0,off=0,imm=0) R10=fp0 fp-176=mmmm????
    15: (b7) r0 = 0
    16: (95) exit
    
    from 14 to 17: R0=map_value(id=0,off=0,ks=4,vs=92,imm=0) R6_w=map_value(id=0,off=0,ks=4,vs=92,imm=0) R7=invP0 R8=ctx(id=0,off=0,imm=0) R10=fp0 fp-176=mmmm????
    17: (b7) r1 = 175
    18: (7b) *(u64 *)(r6 +4) = r1
     R0=map_value(id=0,off=0,ks=4,vs=92,imm=0) R1_w=inv175 R6_w=map_value(id=0,off=0,ks=4,vs=92,imm=0) R7=invP0 R8=ctx(id=0,off=0,imm=0) R10=fp0 fp-176=mmmm????
    19: (b7) r1 = 92
    20: (63) *(u32 *)(r6 +0) = r1
     R0=map_value(id=0,off=0,ks=4,vs=92,imm=0) R1_w=inv92 R6_w=map_value(id=0,off=0,ks=4,vs=92,imm=0) R7=invP0 R8=ctx(id=0,off=0,imm=0) R10=fp0 fp-176=mmmm????
    21: (85) call bpf_ktime_get_ns#5
    22: (7b) *(u64 *)(r6 +12) = r0
     R0=inv(id=0) R6=map_value(id=0,off=0,ks=4,vs=92,imm=0) R7=invP0 R8=ctx(id=0,off=0,imm=0) R10=fp0 fp-176=mmmm????
    23: (85) call bpf_get_current_pid_tgid#14
    24: (7b) *(u64 *)(r6 +20) = r0
     R0_w=inv(id=0) R6=map_value(id=0,off=0,ks=4,vs=92,imm=0) R7=invP0 R8=ctx(id=0,off=0,imm=0) R10=fp0 fp-176=mmmm????
    25: (85) call bpf_get_current_uid_gid#15
    26: (7b) *(u64 *)(r6 +28) = r0
     R0_w=inv(id=0) R6=map_value(id=0,off=0,ks=4,vs=92,imm=0) R7=invP0 R8=ctx(id=0,off=0,imm=0) R10=fp0 fp-176=mmmm????
    27: (85) call bpf_get_current_cgroup_id#80
    28: (7b) *(u64 *)(r6 +36) = r0
     R0_w=inv(id=0) R6=map_value(id=0,off=0,ks=4,vs=92,imm=0) R7=invP0 R8=ctx(id=0,off=0,imm=0) R10=fp0 fp-176=mmmm????
    29: (7b) *(u64 *)(r6 +60) = r7
     R0_w=inv(id=0) R6=map_value(id=0,off=0,ks=4,vs=92,imm=0) R7=invP0 R8=ctx(id=0,off=0,imm=0) R10=fp0 fp-176=mmmm????
    30: (7b) *(u64 *)(r6 +52) = r7
     R0_w=inv(id=0) R6=map_value(id=0,off=0,ks=4,vs=92,imm=0) R7=invP0 R8=ctx(id=0,off=0,imm=0) R10=fp0 fp-176=mmmm????
    31: (7b) *(u64 *)(r6 +44) = r7
     R0_w=inv(id=0) R6=map_value(id=0,off=0,ks=4,vs=92,imm=0) R7=invP0 R8=ctx(id=0,off=0,imm=0) R10=fp0 fp-176=mmmm????
    32: (63) *(u32 *)(r10 -172) = r7
    33: (18) r1 = 0xffff901d8f2eac00
    35: (bf) r2 = r10
    36: (07) r2 += -172
    37: (85) call bpf_map_lookup_elem#1
    etc. Tables don’t seem to be working:
    osquery> select * from bpf_socket_events;
    osquery>
  • a

    alessandrogario

    11 months ago
    thanks for testing this! can you tell me which distro and kernel version are you using?
  • is this still debian stretch with kernel 4.19?
  • z

    Zander Mackie

    11 months ago
    [STD-DEV]19:53:43 zmackie@si-i-0fe66e9061a89d90d ~ $ uname -srm
    Linux 5.4.0-1054-aws x86_64
    [STD-DEV]19:53:45 zmackie@si-i-0fe66e9061a89d90d ~ $ cat /etc/issue
    Ubuntu 18.04.5 LTS \n \l
  • a

    alessandrogario

    11 months ago
    I've updated the PR, hopefully the packages will be created soon by the CI
  • z

    Zander Mackie

    11 months ago
    Ok great. I’ll test it out today.
  • [STD-DEV]16:56:12 root@si-i-02caa65087583c219 /home/zmackie # osqueryi --flagfile=/etc/osquery/osquery.flags --config_path /etc/osquery/osquery.conf --disable_events=false --enable_bpf_events=true --verbose
    I0915 16:56:23.435357  3334 init.cpp:357] osquery initialized [version=5.0.1-5-gd63adb159]
    I0915 16:56:23.435413  3334 extensions.cpp:453] Could not autoload extensions: Cannot open file for reading: /etc/osquery/extensions.load
    I0915 16:56:23.435511  3334 dispatcher.cpp:78] Adding new service: ExtensionWatcher (0x555dd0005ad8) to thread: 139808879249152 (0x555dd0004820) in process 3334
    I0915 16:56:23.435555  3334 dispatcher.cpp:78] Adding new service: ExtensionRunnerCore (0x555dd0005e58) to thread: 139808870856448 (0x555dd0006060) in process 3334
    I0915 16:56:23.435577  3334 auto_constructed_tables.cpp:97] Removing stale ATC entries
    I0915 16:56:23.435611  3336 interface.cpp:299] Extension manager service starting: /root/.osquery/shell.em
    I0915 16:56:23.435998  3334 packs.cpp:177] No queries defined for pack testing
    W0915 16:56:23.436026  3334 config.cpp:755] Error reading the query pack named: osquery-monitoring
    I0915 16:56:23.437970  3334 virtual_table.cpp:1081] Table curl is disabled, not attaching
    I0915 16:56:23.449920  3334 smbios_tables.cpp:105] Reading SMBIOS from sysfs DMI node
    I0915 16:56:23.469677  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall fork (20)
    I0915 16:56:23.474203  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall vfork (28)
    I0915 16:56:23.479529  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall clone (36)
    I0915 16:56:23.482815  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall close (44)
    I0915 16:56:23.486101  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall dup (50)
    I0915 16:56:23.489410  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall dup2 (56)
    I0915 16:56:23.492754  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall dup3 (62)
    I0915 16:56:23.503108  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall creat (71)
    I0915 16:56:23.507138  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall mknod (77)
    I0915 16:56:23.511209  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall mknodat (83)
    I0915 16:56:23.521512  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall open (91)
    I0915 16:56:23.525660  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall openat (97)
    I0915 16:56:23.525754  3334 bpfeventpublisher.cpp:243] Failed to load the BPF probe for syscall openat2: Failed to open the tracepoint descriptor file: /sys/kernel/debug/tracing/events/syscalls/sys_enter_openat2/id. This syscall may not be available on this system, continuing despite the error
    I0915 16:56:23.535298  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall socket (105)
    I0915 16:56:23.538671  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall fcntl (111)
    I0915 16:56:23.542870  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall connect (117)
    I0915 16:56:23.547585  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall accept (123)
    I0915 16:56:23.552459  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall accept4 (129)
    I0915 16:56:23.556568  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall bind (135)
    I0915 16:56:23.559815  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall listen (141)
    I0915 16:56:23.571007  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall chdir (149)
    I0915 16:56:23.574292  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall fchdir (155)
    I0915 16:56:23.579437  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall name_to_handle_at (161)
    I0915 16:56:23.583361  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall open_by_handle_at (167)
    I0915 16:56:23.618160  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall execve (175)
    I0915 16:56:23.646396  3334 bpfeventpublisher.cpp:256] Initialized BPF probe for syscall execveat (181)
    I0915 16:56:23.681736  3334 eventfactory.cpp:156] Event publisher not enabled: auditeventpublisher: Publisher disabled via configuration
    I0915 16:56:23.681777  3334 eventfactory.cpp:156] Event publisher not enabled: syslog: Publisher disabled via configuration
    I0915 16:56:23.681882  3334 events.cpp:70] Skipping subscriber: apparmor_events: Subscriber disabled via configuration
    I0915 16:56:23.681939  3334 events.cpp:70] Skipping subscriber: process_file_events: Subscriber disabled via configuration
    I0915 16:56:23.681952  3334 events.cpp:70] Skipping subscriber: seccomp_events: Seccomp subscriber disabled via configuration
    I0915 16:56:23.681962  3334 events.cpp:70] Skipping subscriber: selinux_events: Subscriber disabled via configuration
    I0915 16:56:23.681978  3334 events.cpp:70] Skipping subscriber: socket_events: Subscriber disabled via configuration
    I0915 16:56:23.682354  3339 eventfactory.cpp:390] Starting event publisher run loop: BPFEventPublisher
    I0915 16:56:23.682379  3340 eventfactory.cpp:390] Starting event publisher run loop: inotify
    Using a virtual database. Need help, type '.help'
    I0915 16:56:23.682407  3341 eventfactory.cpp:390] Starting event publisher run loop: udev
    osquery> I0915 16:56:35.073837  3339 bpfeventpublisher.cpp:341] Lost BPF events counter: 9283
    I0915 16:56:35.110466  3339 bpfeventpublisher.cpp:374] BPFEventPublisher failed to process event from tracer #97
    I0915 16:56:35.118145  3339 bpfeventpublisher.cpp:374] BPFEventPublisher failed to process event from tracer #97
    E0915 16:56:35.182487  3339 bpfeventpublisher.cpp:381] BPFEventPublisher has encountered 2 malformed events
    [STD-DEV]17:02:25 root@si-i-02caa65087583c219 /home/zmackie # echo "select * from osquery_info;" | osqueryi
    W0915 17:02:28.368788 16518 config.cpp:755] Error reading the query pack named: osquery-monitoring
    +-------+--------------------------------------+--------------------------------------+--------------------+------------------------------------------+--------------+------------+----------------+--------------+------------+---------+---------------+
    | pid   | uuid                                 | instance_id                          | version            | config_hash                              | config_valid | extensions | build_platform | build_distro | start_time | watcher | platform_mask |
    +-------+--------------------------------------+--------------------------------------+--------------------+------------------------------------------+--------------+------------+----------------+--------------+------------+---------+---------------+
    | 16518 | ec29909d-71b1-7cd2-d9ee-2bf019d2a31b | f555a96f-e9ff-4da5-9591-434d588ce084 | 5.0.1-5-gd63adb159 | 8f988a69ffeeac0cca33904ed4227b8a06b4d32c | 1            | inactive   | linux          | centos7      | 1631725348 | -1      | 9             |
    +-------+--------------------------------------+--------------------------------------+--------------------+------------------------------------------+--------------+------------+----------------+--------------+------------+---------+---------------+
    [STD-DEV]17:02:29 root@si-i-02caa65087583c219 /home/zmackie #
  • Still seems to be acting up a bit, but the tables are populating at least:
  • a

    alessandrogario

    11 months ago
    You may need to increase the perf output size to solve the following issue:
    I0915 16:56:35.073837  3339 bpfeventpublisher.cpp:341] Lost BPF events counter: 9283
    Events are being lost even before osquery has a chance to look at the perf output
  • That is a message generated by the kernel, whenever it detects that the perf ring buffer has wrapped around, overwriting data we didn't have a chance to read
  • z

    Zander Mackie

    11 months ago
    Gotcha. You know how to tune that offhand? I’m digging…
  • a

    alessandrogario

    11 months ago
  • z

    Zander Mackie

    11 months ago
    TY!
  • That seems to have helped with those lost event counter messages
  • a

    alessandrogario

    11 months ago
    If the fix actually works, could you mention it in the PR with a comments? 🙂
  • I'll look at the memory issue next
  • z

    Zander Mackie

    11 months ago
    I’m still seeing the malformed event warnings, but the lost event counter warnings are gone. Left comments in the PR.
  • a

    alessandrogario

    11 months ago
    I see! I can't update the execve as I did with the other syscalls 😞
  • The filename parameter needs to be capture upon entering the syscalls, because when we are at the exit the original address space is lost