I have been looking at the unified_log table and capabilities in version 5.5.1 and I have seen all queries get denylisted pretty quickly. I have the following query looking for xprotect actions in unified_logs:

select timestamp as time, datetime(timestamp, 'unixepoch') AS utc_time, storage, message, actiity, process, pid, sender, tid, category, subsystem FROM unified_log WHERE (sender = 'AppleSystemPolicy' AND message like '%ASP: Security policy%') and timestamp > -1;

This tends to either get denylisted on first run or on the second. Any thoughts on how to collect this and other data from unified_log without being denylisted would be appreciated.

This is pretty speculative, but does it help at all if you remove the

timestamp > -1

portion? I don't think that timestamp trick was intended to be used along with the other filters, so perhaps it causes the code to hit some less optimized path.

I'll give it a shot, from the description I read it as that was required.

What are your watchdog settings?

on this instance I don't have anything custom in the flags file. Just the default. I started a new agent just to test this capability.

I wonder if the defaults are too conservative? Does it work if you disable the watchdog? Or up the timeouts.

I can definitely try that, I have

watchdog_level=1

now and will see how it goes. The denylist seems to be due to number of restarts. I am getting the log

osquery worker stopping: Memory limits exceeded: 629063680

Maybe if you can, use the shell to execute the query and also provide

--planner

. It should print on the top some information around how many rows are being passed behind the scenes to sqlite, pre sqlite filtering but post table logic filtering. This is likely what’s causing the high amount of memory used. It should print something like:

osquery planner: xFilter unified_log generate returned row count:100

In my case though I see 100 rows correctly being returned; the query is almost the same as yours, I just changed the constraint on

message

, because I don’t have any of those messages

Giving it a go. Thanks for the tip

When I looked at this the filtering was done in the library inside osquery. So it’s possible that even if library is only returning 100 rows it’s doing a ton of work in process to get them. Could be memory mapping the database too which would show up in RSS.

I added some flags to my flag file

--watchdog_level=0

--watchdog_memory_limit=600

Also ran the profiling script

./tools/analysis/profile.py --shell /usr/local/bin/osqueryi --config /var/osquery/osquery.conf --rounds 4 --count 10
Profiling query: SELECT timestamp as time, datetime(timestamp, 'unixepoch') AS utc_time, storage, message, activity, process, pid, sender, tid, category, subsystem, level FROM unified_log WHERE (sender = 'AppleSystemPolicy' AND message LIKE '%ASP: Security policy%');
 U:0  C:0  M:2  F:0  D:0  pack_xprotect_action (1/4): utilization: 2.0 cpu_time: 0.02026575 memory: 16531456 fds: 4 duration: 0.5249452590942383
 U:0  C:0  M:2  F:0  D:0  pack_xprotect_action (2/4): utilization: 2.5 cpu_time: 0.026586916 memory: 16596992 fds: 4 duration: 0.5433149337768555
 U:0  C:0  M:2  F:0  D:0  pack_xprotect_action (3/4): utilization: 3.75 cpu_time: 0.038514957 memory: 17301504 fds: 4 duration: 0.5454161167144775
 U:0  C:0  M:2  F:0  D:0  pack_xprotect_action (4/4): utilization: 3.6 cpu_time: 0.037013833999999995 memory: 17006592 fds: 4 duration: 0.53110671043396
 U:0  C:0  M:2  F:0  D:0  pack_xprotect_action   avg: utilization: 2.9625 cpu_time: 0.03059536425 memory: 16859136.0 fds: 4.0 duration: 0.5361957550048828

The evented style behavior requires

timestamp > -1

as a condition.

That is what I thought originally but in a previous reply @zwass suggested removing that. I'll place it back in the query and restart the service https://osquery.slack.com/archives/C08VA8R6F/p1666034239835079?thread_ts=1666031180.257089&cid=C08VA8R6F

Try to delete the internal database between tests (

osquery.db

), it will reset the internal pointer of the evented style (

timestamp > -1

).