Title
#macos
l

lvferdi

10/17/2022, 6:26 PM
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.
zwass

zwass

10/17/2022, 7:17 PM
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.
l

lvferdi

10/17/2022, 7:18 PM
I'll give it a shot, from the description I read it as that was required.
7:46 PM
@zwass that didn't make a difference. Thanks again, worth a shot
s

seph

10/17/2022, 7:50 PM
What are your watchdog settings?
l

lvferdi

10/17/2022, 7:52 PM
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.
s

seph

10/17/2022, 7:53 PM
I wonder if the defaults are too conservative? Does it work if you disable the watchdog? Or up the timeouts.
l

lvferdi

10/17/2022, 7:59 PM
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
Stefano Bonicatti

Stefano Bonicatti

10/18/2022, 11:04 AM
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
11:05 AM
I would also keep an eye on memory usage from the shell and see if the high memory usage consumption reproduces.
l

lvferdi

10/18/2022, 1:01 PM
Giving it a go. Thanks for the tip
1:02 PM
Also @Stefano Bonicatti I just compiled a hello world app with a matching yara sig. it’s benign but trips xprotect and shows the logs. Happy to share if you want 1:1 testing
1:35 PM
output from planner
Ryan Mack

Ryan Mack

10/18/2022, 5:08 PM
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.
l

lvferdi

10/18/2022, 6:23 PM
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
6:23 PM
Doesn't look bad.......
11:53 AM
Commenting and tagging outside of the thread for visibility, after the watchdog tweaks and removing the time constraint from the query it appears that I can get the queries to run against the unified log without crashing the agent, but every time the query is run I am getting back all results. The table is not acting like an evented table as I thought was the intention. Instead, every time this query runs, I get back all entries in unified, not just last N entries since last run
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%');
s

seph

10/19/2022, 12:44 PM
The evented style behavior requires
timestamp > -1
as a condition.
l

lvferdi

10/19/2022, 1:09 PM
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
Daniel Bretón Suárez

Daniel Bretón Suárez

11/04/2022, 10:54 AM
Try to delete the internal database between tests (
osquery.db
), it will reset the internal pointer of the evented style (
timestamp > -1
).