[BUG] Timestamp incorrect in event logs, dated in the future by 7 days/1 week #932
Comments
|
Hi Stanley, thanks for reporting this. During development of #595 you linked to I noticed some time travel issues as well, that is why I force changed my entire dev Linux box to UTC not just the configs and then the times made sense again. What was changed in above PR was the derivation of the host boot ts, new approach vs we kept the old one as fall-back. Rest of the changes were around the new fields introduced so they are unrelated. The new approach to derive boot time is the same approach we use to derive the process start time when doing the initial proc scan. Boot time is involved in deriving epochs when the kernel only offers monotonic times. Wondering if someone has more context around this? |
|
I've seen this in using the falco libs separately from falco. Tried to reproduced in sinsp-example/scap-example from the head of libs and haven't been able to replicate currently. Will keep digging. |
Same here, never seen this issue with |
|
Hey team, Did some preliminary investigation:
Will do some more digging as time permits. My next "excavation" will be where/how the timestamp is recorded when an event is traced/processed. |
|
yeah probably I would try to reproduce it with the |
|
maybe we could also write some tests in sinsp to try to spot it 🤔 |
|
Hey team, Thanks for the pointers in this ticket, the Slack discussion, and the community call. I was able to reproduce the erroneous timestamp on one of my Falco-evaluation systems by building the Additionally, I can validate that all the hosts I am evaluating Falco on reports an incorrect timestamp; the timestamp "offset" is inconsistent and does not seem to stem from incrementing the correct timestamps by the same amount. Here is a sample output (note: I'm not sure I'm using the Any guidance on next steps to debug further? EDIT: |
|
I think a next good step, is to trace through where the ts value gets set in the scap_evt object. Could add a print statement there, to see if the timestamp changes from assignment to where it's being printed in scap-example. |
|
Hey, @happy-dude this is not a bug is a feature! In this way you can read events from the future! 🤣 scpa-open usage libs/driver/ppm_events_public.h Line 1098 in f5412a4 So in this case if you want the execve exit event you have to use --evt_type 293. The full command will be
sudo ./libscap/examples/01-open/scap-open --modern_bpf --evt_type 293 --num_events 10Probably timestamp issue Coming back to the issue, I've tried the same scap-open setup but again i didn't see almost anything strange :( BTW looking at your data it seems that the boot time in your case is completely wrong. The event timestamp is composed of 2 parts: the boot_time and the number of nanosecond from the boot_time. The boot_time is computed at initialization time by us, while the nanoseconds from the boot_time are provided by a bpf helper hdr->ts = maps__get_boot_time() + bpf_ktime_get_boot_ns();Now supposing that there is no bug in the bpf helper (this doesn't seem the case because if I look at the increment of your events in the scap-open logs I can see that the increment in nanoseconds seems almost good) probably there is something wrong in the boot time computation... Another possible test would be to use |
|
@happy-dude i'd also check the output of |
Awesome, appreciate the context + explanation and will use this command.
Just built a new
No problem! See the following: |
|
So, the issue here is that |
|
Awesome awesome; any further actions on my side atm? If this might be a specific config in our environment, I can discuss with internal teams on why this might be the case. Also forgot to answer Andrea re: kmod option; unfortunately, won't be able to do this easily on my side as loading kernel modules would require communication, approvals, etc. with my org and stakeholders. |
|
Can you share |
|
|
You know what ahhaah there is no issues here, just that sites like epochconverter automatically switch base depending on number of digits of the number.
Using another tool, ie: https://www.epoch101.com/, you'll discover that:
Basically, the even is happening ~22days after you booted up your PC (and that is a validated information from your The issue here is not about events timestamp, but is all about why your |
|
Can you share also |
|
|
Perhaps you are mounting your proc filesystem with |
|
|
I've updated our test branch removing this proc scan and using the old fallback logic https://github.com/Andreagit97/libs/tree/timestamp_issue. Would you like to give it a try @happy-dude? |
|
Just built and ran: |
|
ok with this method timestamps have again some sense:
So just to have a summary:
Not sure what we want to do here, this |
|
on your side @happy-dude it would be amazing to understand why in all your machines |
|
Yep :( |
Yup yup, will ask around! For additional info, what was the context/rational for using this method for calculating the boot time? Was the fallback method used until the |
|
The BUT small plot twist: I'm building EDIT: was unable to reproduce with Will work to track down the problem on ARM first and provide context there first. |
|
Just created a patch; happy to incorporate any feedback! I tested it briefly on the ARM system and it looked alright, could use more testing and validation though 🙏 |
…on time See falcosecurity#932 for more context Previous: ```c snprintf(proc_dir, sizeof(proc_dir), "%s/proc/1/", scap_get_host_root()); ``` This PR: ```c snprintf(proc_cmdline, sizeof(proc_cmdline), "%s/proc/1/cmdline", scap_get_host_root()); ``` Signed-off-by: Stanley Chan <[email protected]>
…on time See falcosecurity#932 for more context Change occurrences of `/proc/1` to `/proc/1/cmdline` in * userspace/libscap/linux/scap_procs.c * userspace/libscap/scap.c Previous: ```c snprintf(proc_dir, sizeof(proc_dir), "%s/proc/1/", scap_get_host_root()); ``` This PR: ```c snprintf(proc_cmdline, sizeof(proc_cmdline), "%s/proc/1/cmdline", scap_get_host_root()); ``` Signed-off-by: Stanley Chan <[email protected]>
|
Unfortunate news: The change didn't fix the timestamp on my nodes; it's possible that Changed the PR to (WIP) Internally to my org, there may be separate issues affecting EDIT: I'm also discussing with my team on if we can patch our builds to use the fall back method w/ Here is some output from scap_open: |
|
Yes I think that would be a great data point for us to see if the old approach works. In addition, surfing the internet for any options available e.g. see this, maybe it would be helpful to check on all of them just to give all of us more information to work with and help. Anyone else having more ideas? Also would it perhaps be possible to reboot one server and check again on all options? |
Possible depending on which option; essentially have to make new packages iterating through each because config management will install the latest package in our repo on my evaluation hosts 😅
I'll look to creating a package that comments out the boot time code in Does that mean I also need to undo the |
|
Maybe just run the different commands from a shell first to check?
Let's just go with Andrea's suggestion to see the old approach, plus would be curious about the outputs of the bash commands in that post to know if any of the other options gives the correct boot ts. |
What do you mean by "The change didn't fix the timestamp on my nodes"? if I understand correctly now using |
Apologies for lack of context; with the output from #932 (comment), at the time this was a system I rebooted ~1 hour before -- unfortunately, This makes our assumption that We're discussing this a bit further in the Slack on our other options (I added you to the group!), and perhaps something else in procfs may prove useful! |
Get boot time from btime value in /proc/stat ref: falcosecurity#932 /proc/uptime and btime in /proc/stat are fed by the same kernel sources. Multiple ways to get boot time: * btime in /proc/stat * calculation via clock_gettime(CLOCK_REALTIME - CLOCK_BOOTTIME) * calculation via time(NULL) - sysinfo().uptime Maintainers preferred btime in /proc/stat because: * value does not depend on calculation using current timestamp * btime is "static" and doesn't change once set * btime is available in kernels from 2008 * CLOCK_BOOTTIME is available in kernels from 2011 (2.6.38 By scraping btime from /proc/stat, it is both the heaviest and most likely to succeed Signed-off-by: Stanley Chan <[email protected]> Co-authored-by: Melissa Kilby [email protected]
…on time See falcosecurity#932 for more context Change occurrences of `/proc/1` to `/proc/1/cmdline` in * userspace/libscap/linux/scap_procs.c * userspace/libscap/scap.c Previous: ```c snprintf(proc_dir, sizeof(proc_dir), "%s/proc/1/", scap_get_host_root()); ``` This PR: ```c snprintf(proc_cmdline, sizeof(proc_cmdline), "%s/proc/1/cmdline", scap_get_host_root()); ``` Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected] Signed-off-by: Stanley Chan <[email protected]>
Get boot time from btime value in /proc/stat ref: falcosecurity#932 /proc/uptime and btime in /proc/stat are fed by the same kernel sources. Multiple ways to get boot time: * btime in /proc/stat * calculation via clock_gettime(CLOCK_REALTIME - CLOCK_BOOTTIME) * calculation via time(NULL) - sysinfo().uptime Maintainers preferred btime in /proc/stat because: * value does not depend on calculation using current timestamp * btime is "static" and doesn't change once set * btime is available in kernels from 2008 * CLOCK_BOOTTIME is available in kernels from 2011 (2.6.38) By scraping btime from /proc/stat, it is both the heaviest and most likely to succeed Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected] Signed-off-by: Stanley Chan <[email protected]>
…on time See falcosecurity#932 for more context Change occurrences of `/proc/1` to `/proc/1/cmdline` in * userspace/libscap/linux/scap_procs.c * userspace/libscap/scap.c Previous: ```c snprintf(proc_dir, sizeof(proc_dir), "%s/proc/1/", scap_get_host_root()); ``` This PR: ```c snprintf(proc_cmdline, sizeof(proc_cmdline), "%s/proc/1/cmdline", scap_get_host_root()); ``` Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
Get boot time from btime value in /proc/stat ref: falcosecurity#932 /proc/uptime and btime in /proc/stat are fed by the same kernel sources. Multiple ways to get boot time: * btime in /proc/stat * calculation via clock_gettime(CLOCK_REALTIME - CLOCK_BOOTTIME) * calculation via time(NULL) - sysinfo().uptime Maintainers preferred btime in /proc/stat because: * value does not depend on calculation using current timestamp * btime is "static" and doesn't change once set * btime is available in kernels from 2008 * CLOCK_BOOTTIME is available in kernels from 2011 (2.6.38) By scraping btime from /proc/stat, it is both the heaviest and most likely to succeed Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
Get boot time from btime value in /proc/stat ref: falcosecurity#932 /proc/uptime and btime in /proc/stat are fed by the same kernel sources. Multiple ways to get boot time: * btime in /proc/stat * calculation via clock_gettime(CLOCK_REALTIME - CLOCK_BOOTTIME) * calculation via time(NULL) - sysinfo().uptime Maintainers preferred btime in /proc/stat because: * value does not depend on calculation using current timestamp * btime is "static" and doesn't change once set * btime is available in kernels from 2008 * CLOCK_BOOTTIME is available in kernels from 2011 (2.6.38) By scraping btime from /proc/stat, it is both the heaviest and most likely to succeed Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
|
Just updated the PR and added a comment, #1003 (comment)
|
Get boot time from btime value in /proc/stat ref: falcosecurity#932 /proc/uptime and btime in /proc/stat are fed by the same kernel sources. Multiple ways to get boot time: * btime in /proc/stat * calculation via clock_gettime(CLOCK_REALTIME - CLOCK_BOOTTIME) * calculation via time(NULL) - sysinfo().uptime Maintainers preferred btime in /proc/stat because: * value does not depend on calculation using current timestamp * btime is "static" and doesn't change once set * btime is available in kernels from 2008 * CLOCK_BOOTTIME is available in kernels from 2011 (2.6.38) By scraping btime from /proc/stat, it is both the heaviest and most likely to succeed Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
Get boot time from btime value in /proc/stat ref: falcosecurity#932 /proc/uptime and btime in /proc/stat are fed by the same kernel sources. Multiple ways to get boot time: * btime in /proc/stat * calculation via clock_gettime(CLOCK_REALTIME - CLOCK_BOOTTIME) * calculation via time(NULL) - sysinfo().uptime Maintainers preferred btime in /proc/stat because: * value does not depend on calculation using current timestamp * btime is "static" and doesn't change once set * btime is available in kernels from 2008 * CLOCK_BOOTTIME is available in kernels from 2011 (2.6.38) By scraping btime from /proc/stat, it is both the heaviest and most likely to succeed Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
Get boot time from btime value in /proc/stat ref: falcosecurity#932 /proc/uptime and btime in /proc/stat are fed by the same kernel sources. Multiple ways to get boot time: * btime in /proc/stat * calculation via clock_gettime(CLOCK_REALTIME - CLOCK_BOOTTIME) * calculation via time(NULL) - sysinfo().uptime Maintainers preferred btime in /proc/stat because: * value does not depend on calculation using current timestamp * btime is "static" and doesn't change once set * btime is available in kernels from 2008 * CLOCK_BOOTTIME is available in kernels from 2011 (2.6.38) By scraping btime from /proc/stat, it is both the heaviest and most likely to succeed Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
Get boot time from btime value in /proc/stat ref: falcosecurity#932 /proc/uptime and btime in /proc/stat are fed by the same kernel sources. Multiple ways to get boot time: * btime in /proc/stat * calculation via clock_gettime(CLOCK_REALTIME - CLOCK_BOOTTIME) * calculation via time(NULL) - sysinfo().uptime Maintainers preferred btime in /proc/stat because: * value does not depend on calculation using current timestamp * btime is "static" and doesn't change once set * btime is available in kernels from 2008 * CLOCK_BOOTTIME is available in kernels from 2011 (2.6.38) By scraping btime from /proc/stat, it is both the heaviest and most likely to succeed Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
…on time See falcosecurity#932 for more context Change occurrences of `/proc/1` to `/proc/1/cmdline` in * userspace/libscap/linux/scap_procs.c * userspace/libscap/scap.c Previous: ```c snprintf(proc_dir, sizeof(proc_dir), "%s/proc/1/", scap_get_host_root()); ``` This PR: ```c snprintf(proc_cmdline, sizeof(proc_cmdline), "%s/proc/1/cmdline", scap_get_host_root()); ``` Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
Get boot time from btime value in /proc/stat ref: falcosecurity#932 /proc/uptime and btime in /proc/stat are fed by the same kernel sources. Multiple ways to get boot time: * btime in /proc/stat * calculation via clock_gettime(CLOCK_REALTIME - CLOCK_BOOTTIME) * calculation via time(NULL) - sysinfo().uptime Maintainers preferred btime in /proc/stat because: * value does not depend on calculation using current timestamp * btime is "static" and doesn't change once set * btime is available in kernels from 2008 * CLOCK_BOOTTIME is available in kernels from 2011 (2.6.38) By scraping btime from /proc/stat, it is both the heaviest and most likely to succeed Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
Get boot time from btime value in /proc/stat ref: falcosecurity#932 /proc/uptime and btime in /proc/stat are fed by the same kernel sources. Multiple ways to get boot time: * btime in /proc/stat * calculation via clock_gettime(CLOCK_REALTIME - CLOCK_BOOTTIME) * calculation via time(NULL) - sysinfo().uptime Maintainers preferred btime in /proc/stat because: * value does not depend on calculation using current timestamp * btime is "static" and doesn't change once set * btime is available in kernels from 2008 * CLOCK_BOOTTIME is available in kernels from 2011 (2.6.38) By scraping btime from /proc/stat, it is both the heaviest and most likely to succeed Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
Get boot time from btime value in /proc/stat ref: falcosecurity#932 /proc/uptime and btime in /proc/stat are fed by the same kernel sources. Multiple ways to get boot time: * btime in /proc/stat * calculation via clock_gettime(CLOCK_REALTIME - CLOCK_BOOTTIME) * calculation via time(NULL) - sysinfo().uptime Maintainers preferred btime in /proc/stat because: * value does not depend on calculation using current timestamp * btime is "static" and doesn't change once set * btime is available in kernels from 2008 * CLOCK_BOOTTIME is available in kernels from 2011 (2.6.38) By scraping btime from /proc/stat, it is both the heaviest and most likely to succeed Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
See #932 for more context Change occurrences of `/proc/1` to `/proc/1/cmdline` in * userspace/libscap/linux/scap_procs.c * userspace/libscap/scap.c Previous: ```c snprintf(proc_dir, sizeof(proc_dir), "%s/proc/1/", scap_get_host_root()); ``` This PR: ```c snprintf(proc_cmdline, sizeof(proc_cmdline), "%s/proc/1/cmdline", scap_get_host_root()); ``` Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
Get boot time from btime value in /proc/stat ref: #932 /proc/uptime and btime in /proc/stat are fed by the same kernel sources. Multiple ways to get boot time: * btime in /proc/stat * calculation via clock_gettime(CLOCK_REALTIME - CLOCK_BOOTTIME) * calculation via time(NULL) - sysinfo().uptime Maintainers preferred btime in /proc/stat because: * value does not depend on calculation using current timestamp * btime is "static" and doesn't change once set * btime is available in kernels from 2008 * CLOCK_BOOTTIME is available in kernels from 2011 (2.6.38) By scraping btime from /proc/stat, it is both the heaviest and most likely to succeed Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
…on time See falcosecurity#932 for more context Change occurrences of `/proc/1` to `/proc/1/cmdline` in * userspace/libscap/linux/scap_procs.c * userspace/libscap/scap.c Previous: ```c snprintf(proc_dir, sizeof(proc_dir), "%s/proc/1/", scap_get_host_root()); ``` This PR: ```c snprintf(proc_cmdline, sizeof(proc_cmdline), "%s/proc/1/cmdline", scap_get_host_root()); ``` Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
Get boot time from btime value in /proc/stat ref: falcosecurity#932 /proc/uptime and btime in /proc/stat are fed by the same kernel sources. Multiple ways to get boot time: * btime in /proc/stat * calculation via clock_gettime(CLOCK_REALTIME - CLOCK_BOOTTIME) * calculation via time(NULL) - sysinfo().uptime Maintainers preferred btime in /proc/stat because: * value does not depend on calculation using current timestamp * btime is "static" and doesn't change once set * btime is available in kernels from 2008 * CLOCK_BOOTTIME is available in kernels from 2011 (2.6.38) By scraping btime from /proc/stat, it is both the heaviest and most likely to succeed Co-authored-by: Grzegorz Nosek <[email protected]> Co-authored-by: Melissa Kilby <[email protected]> Signed-off-by: Stanley Chan <[email protected]>
Describe the bug
While analyzing event and debug logs generated by Falco, we discovered that the events were dated in the future.
For example, we saw an debug entry on
1677527444(aroundMon, 27 Feb 2023 19:50:44 GMT), I identified the following entry with the following timestamp2023-03-06T11:56:34.693685797Z:Around an event generated on
The following event was observed with timestamp
1678109229443642000,2023-03-06T13:27:09.443642063Z:How to reproduce it
Unsure, installation was from HEAD @ 0de9af9 via systemd on-metal.
Generate events and look at log messages?
Expected behaviour
Timestamp should be accurate / not in the future.
Since the epoch times are pretty similar,
1678109229443642000and1677527950; perhaps the string generated in thetimefield is incorrect (~7 days in the future, or6048000000000in nanoseconds epoch)?Environment
Additional context
Possibly related to #595 ? (Did a search from prior PRs related to
time.)Discussion on Slack community: https://kubernetes.slack.com/archives/CMWH3EH32/p1677517061599169
The text was updated successfully, but these errors were encountered: