Metrics are not created if http_output is enabled

[annadorottya]

Describe the bug

If http_output is enabled, then only one metric alert is created / only one line is written in the metrics log file regardless the set period.

How to reproduce it

Set config to:

http_output:
  enabled: true
  url: http://some.url
metrics:
  enabled: true
  interval: 1m
  output_rule: true
  output_file: /tmp/falco_stats.jsonl

Expected behaviour

Metrics alerts are created every minute and written to the /tmp/falco_stats.jsonl file every minute.

Screenshots

Environment

• Falco version:

2023-06-21T03:38:30+0000: Falco version: 0.35.0 (x86_64)
2023-06-21T03:38:30+0000: Falco initialized with configuration file: /etc/falco/falco.yaml
Falco version: 0.35.0
Libs version:  0.11.2
Plugin API:    3.0.0
Engine:        17
Driver:
  API version:    4.0.0
  Schema version: 2.0.0
  Default driver: 5.0.1+driver

• System info:

  "machine": "x86_64",
  "nodename": "falco-syscall-b2h8x",
  "release": "5.15.89+",
  "sysname": "Linux",
  "version": "#1 SMP Sat Mar 11 10:24:08 UTC 2023"
}

• Cloud provider or hardware configuration: GCP
• OS: Debian GNU/Linux 11 (bullseye)

• Kernel:

Linux falco-syscall-b2h8x 5.15.89+ #1 SMP Sat Mar 11 10:24:08 UTC 2023 x86_64 GNU/Linux

• Installation method: kubernetes

Additional context
Thread on kubernetes slack workspace: https://kubernetes.slack.com/archives/CMWH3EH32/p1686643450242449
@incertum @Issif @alacuku @jasondellaluce

[incertum]

Thanks for reporting this Anna and help us iron out these things to be able to get the metrics feature into a stable state for the next Falco release. We will look into it, thanks for your patience!

[FedeDP]

Hey @annadorottya can you share Falco startup logs? Just in case there is any warning :)

[annadorottya]

Hi @FedeDP ,
sure :)

2023-06-21T07:48:40.469260380Z * Setting up /usr/src links from host
2023-06-21T07:48:40.484757867Z * Running falco-driver-loader for: falco version=0.35.0, driver version=5.0.1+driver, arch=x86_64, kernel release=5.15.89+, kernel version=1
2023-06-21T07:48:40.489162085Z * Running falco-driver-loader with: driver=bpf, compile=yes, download=yes
2023-06-21T07:48:40.489433397Z * Mounting debugfs
2023-06-21T07:48:40.491810152Z mount: /sys/kernel/debug: cannot mount nodev read-only.
2023-06-21T07:48:40.492310324Z * Filename 'falco_cos_5.15.89+_1.o' is composed of:
2023-06-21T07:48:40.492329422Z  - driver name: falco
2023-06-21T07:48:40.492336583Z  - target identifier: cos
2023-06-21T07:48:40.492352167Z  - kernel release: 5.15.89+
2023-06-21T07:48:40.492358559Z  - kernel version: 1
2023-06-21T07:48:40.495684607Z * Trying to download a prebuilt eBPF probe from https://download.falco.org/driver/5.0.1%2Bdriver/x86_64/falco_cos_5.15.89%2B_1.o
2023-06-21T07:48:41.370448912Z curl: (22) The requested URL returned error: 404 
2023-06-21T07:48:41.372255538Z Unable to find a prebuilt falco eBPF probe
2023-06-21T07:48:41.372312599Z * COS detected (build 17162.127.33), using COS kernel headers
2023-06-21T07:48:41.372321949Z * Found kernel config at /proc/config.gz
2023-06-21T07:48:41.377714809Z * Downloading https://storage.googleapis.com/cos-tools/17162.127.33/kernel-headers.tgz
2023-06-21T07:48:42.648673287Z * Extracting kernel sources
2023-06-21T07:48:44.273724707Z * Configuring kernel
2023-06-21T07:48:44.293460602Z * Trying to compile the eBPF probe (falco_cos_5.15.89+_1.o)
2023-06-21T07:48:44.560743400Z warning: the compiler differs from the one used to build the kernel
2023-06-21T07:48:44.560809249Z   The kernel was built by: Chromium OS 14.0_pre445002_p20220217-r3 clang version 14.0.0 (/var/tmp/portage/sys-devel/llvm-14.0_pre445002_p20220217-r3/work/llvm-14.0_pre445002_p20220217/clang 18308e171b5b1dd99627a4d88c7d6c5ff21b8c96)
2023-06-21T07:48:44.560832751Z   You are using:           gcc (Debian 5.5.0-12) 5.5.0 20171010
2023-06-21T07:48:54.740398684Z scripts/mod/modpost: /lib/x86_64-linux-gnu/libc.so.6: version `GLIBC_2.33' not found (required by scripts/mod/modpost)
2023-06-21T07:48:54.741571025Z make[2]: *** [scripts/Makefile.modpost:133: /usr/src/falco-5.0.1+driver/bpf/Module.symvers] Error 1
2023-06-21T07:48:54.742253289Z make[1]: *** [Makefile:1817: modules] Error 2
2023-06-21T07:48:54.742947389Z make: *** [Makefile:38: all] Error 2
2023-06-21T07:48:55.458135044Z * eBPF probe located in /root/.falco/5.0.1+driver/x86_64/falco_cos_5.15.89+_1.o
2023-06-21T07:48:55.459862254Z * Success: eBPF probe symlinked to /root/.falco/falco-bpf.o
2023-06-21T07:48:56.415638570Z INFO: Reading all configured index files from \"/root/.config/falcoctl/indexes.yaml\"
2023-06-21T07:48:56.415686180Z WARN: No configured index. Consider to configure one using the 'index add' command.
2023-06-21T07:48:56.416109972Z INFO: Installing the following artifacts: [ghcr.io/falcosecurity/rules/falco-rules:0.1.0]
2023-06-21T07:48:56.416130258Z INFO: Preparing to pull \"ghcr.io/falcosecurity/rules/falco-rules:0.1.0\"
2023-06-21T07:48:56.418340951Z INFO: Retrieving credentials from local store
2023-06-21T07:48:56.418361230Z INFO: proceeding with empty credentials for registry \"ghcr.io\"
2023-06-21T07:48:57.816487037Z INFO: Pulling ad24f8acf278
2023-06-21T07:48:58.029822215Z INFO: Pulling 0d3705a4650f
2023-06-21T07:48:58.030512969Z INFO: Pulling 0957c1ef3fe4
2023-06-21T07:48:58.030565224Z \r                                                                                \rINFO: Extracting and installing \"rulesfile\" \"falco_rules.yaml.tar.gz\"
2023-06-21T07:48:58.033890279Z \r                                                                                \rINFO: Artifact successfully installed in \"/rulesfiles\"
2023-06-21T07:48:58.380583732Z 2023-06-21T07:48:58+0000: Falco version: 0.35.0 (x86_64)
2023-06-21T07:48:58.381106665Z 2023-06-21T07:48:58+0000: Falco initialized with configuration file: /etc/falco/falco.yaml
2023-06-21T07:48:58.382865141Z 2023-06-21T07:48:58+0000: Loading rules from file /etc/falco/falco_rules.yaml
2023-06-21T07:48:58.586538510Z INFO: Retrieving versions from Falco (timeout 2m0s) ...
2023-06-21T07:48:58.587124813Z INFO: error: dial tcp 127.0.0.1:8765: connect: connection refused. Trying again in 1s
2023-06-21T07:48:58.601574549Z 2023-06-21T07:48:58+0000: The chosen syscall buffer dimension is: 8388608 bytes (8 MBs)
2023-06-21T07:48:58.601624458Z 2023-06-21T07:48:58+0000: Starting health webserver with threadiness 2, listening on port 8765
2023-06-21T07:48:58.602157344Z 2023-06-21T07:48:58+0000: Setting metrics interval to 2m, equivalent to 120000 (ms)
2023-06-21T07:48:58.602336126Z 2023-06-21T07:48:58+0000: Enabled event sources: syscall
2023-06-21T07:48:58.602479691Z 2023-06-21T07:48:58+0000: Opening 'syscall' source with BPF probe. BPF probe path: /root/.falco/falco-bpf.o
2023-06-21T07:48:59.588891413Z INFO: Successfully retrieved versions from Falco ...
2023-06-21T07:48:59.589891660Z INFO: Reading all configured index files from \"/root/.config/falcoctl/indexes.yaml\"
2023-06-21T07:48:59.590118490Z WARN: No configured index. Consider to configure one using the 'index add' command.
2023-06-21T07:48:59.590732616Z INFO: Creating follower for \"falco-rules:0.1.0\", with check every 6h0m0s
2023-06-21T07:48:59.591704445Z INFO: Retrieving credentials from local store
2023-06-21T07:48:59.592268450Z INFO: proceeding with empty credentials for registry \"ghcr.io\"
2023-06-21T07:48:59.782249817Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[39m\u001b[39mStarting follower for \"ghcr.io/falcosecurity/rules/falco-rules:0.1.0\"\u001b[0m\u001b[0m
2023-06-21T07:48:59.782544450Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39mfetching descriptor from remote repository...\u001b[0m\u001b[0m
2023-06-21T07:49:00.341047530Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39mdescriptor correctly fetched\u001b[0m\u001b[0m
2023-06-21T07:49:00.341106774Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39mfound new version under tag \"0.1.0\"\u001b[0m\u001b[0m
2023-06-21T07:49:01.150007995Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39mpulling artifact from remote repository...\u001b[0m\u001b[0m
2023-06-21T07:49:01.150336583Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39mcheck if pulling an allowed type of artifact\u001b[0m\u001b[0m
2023-06-21T07:49:01.355138336Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39mpulling artifact \"ghcr.io/falcosecurity/rules/falco-rules:0.1.0\"\u001b[0m\u001b[0m
2023-06-21T07:49:02.205363845Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39mextracting artifact\u001b[0m\u001b[0m
2023-06-21T07:49:02.210041633Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39mcleaning up leftovers files\u001b[0m\u001b[0m
2023-06-21T07:49:02.210864186Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39martifact correctly pulled\u001b[0m\u001b[0m
2023-06-21T07:49:02.211453834Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39minstalling file \"falco_rules.yaml\"...\u001b[0m\u001b[0m
2023-06-21T07:49:02.212039632Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39mchecking if file \"falco_rules.yaml\" already exists in \"/rulesfiles\"\u001b[0m\u001b[0m
2023-06-21T07:49:02.212660039Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39mfile \"falco_rules.yaml\" already exists in \"/rulesfiles\", checking if it is equal to the existing one\u001b[0m\u001b[0m
2023-06-21T07:49:02.215332514Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39mthe two file are equal, nothing to be done\u001b[0m\u001b[0m
2023-06-21T07:49:02.215915405Z \u001b[39m\u001b[39m INFO \u001b[0m\u001b[0m \u001b[90m\u001b[90m (ghcr.io/falcosecurity/rules/falco-rules:0.1.0) \u001b[0m\u001b[0m\u001b[39m\u001b[39martifact with tag \"0.1.0\" correctly installed\u001b[0m\u001b[0m

[FedeDP]

I am not able to repro locally unfortunately; but can repro with:

• Falco 0.35 tar.gz package
• Falco master tar.gz package

They both just show 2 messages and then stop:

11:00:53.329126198: Informational Falco metrics snapshot (evt.source="syscall" evt.time=1687338053329126198 falco.cpu_usage_perc=57.5 falco.duration_sec=1 falco.host_boot_ts=1687333957000000000 falco.host_num_cpus=8 falco.hostname="fededp-sysdig" falco.kernel_release="6.3.6-arch1-1" falco.memory_pss=76 falco.memory_rss=112 falco.memory_vsz=565 falco.num_evts=446 falco.num_evts_prev=0 falco.start_ts=1687338052229601176 falco.version="0.35.0-16+2b90822" scap.engine_name="modern_bpf" scap.evts_drop_rate_sec=0.0 scap.evts_rate_sec=0.0 scap.n_drops=0 scap.n_drops_perc=0.0 scap.n_drops_prev=0 scap.n_evts=468 scap.n_evts_prev=0)
Wed Jun 21 11:00:53 2023: libcurl error: Couldn't resolve host name
11:00:54.390075498: Informational Falco metrics snapshot (evt.source="syscall" evt.time=1687338054390075498 falco.cpu_usage_perc=30.6 falco.duration_sec=2 falco.evts_rate_sec=1483.5770191846113 falco.host_boot_ts=1687333957000000000 falco.host_num_cpus=8 falco.hostname="fededp-sysdig" falco.kernel_release="6.3.6-arch1-1" falco.memory_pss=76 falco.memory_rss=112 falco.memory_vsz=694 falco.num_evts=2020 falco.num_evts_prev=446 falco.start_ts=1687338052229601176 falco.version="0.35.0-16+2b90822" scap.engine_name="modern_bpf" scap.evts_drop_rate_sec=0.0 scap.evts_rate_sec=1500.5429571422496 scap.n_drops=0 scap.n_drops_perc=0.0 scap.n_drops_prev=0 scap.n_evts=2060 scap.n_evts_prev=468)
Wed Jun 21 11:00:54 2023: libcurl error: Couldn't resolve host name
^CWed Jun 21 11:00:57 2023: SIGINT received, exiting...
Syscall event drop monitoring:
   - event drop detected: 0 occurrences
   - num times actions taken: 0
Events detected: 0
Rule counts by severity:
Triggered rules by rule name:

This makes me think that the issue lies somewhere in the build toolchain (ie: gcc version used in our CI) and in this logic: https://github.com/falcosecurity/falco/blob/master/userspace/falco/stats_writer.cpp#L150 (perhaps the timer_handler: https://github.com/falcosecurity/falco/blob/master/userspace/falco/stats_writer.cpp#L37 ?)

I will push some debug printf to trigger a build from CI and then i'll try to understand what's going on :) This seems a subtle but very funny bug, thank you for reporting it!

[FedeDP]

Ok i was able to fix the issue by switching to timer_settime API; most probably, it was an issue with ancient glibc/gcc used by our CI (that builds on centos7) and setitimer.

[FedeDP]

Falco 0.35.1 is out and should've fixed this issue! @annadorottya care to test? Thank you!

[annadorottya]

Falco 0.35.1 is out and should've fixed this issue! @annadorottya care to test? Thank you!

I tested it and it works! Thank you for the quick fix!

[FedeDP]

Thanks to you for reporting the issue! :)