https://github.com/osquery/osquery logo
Join Slack
Powered by
Hi guys, I am having a problem with osquery on mac...
# general
j
Hi guys, I am having a problem with osquery on macos. I believe it's actually a bug, but I just started to work with osquery 2 days ago. Where would be a good place to ask? Googling does not help. What I notice is a lot duplicated events (different eid, same timestamp). It seems to boil down to duplication of subscribers for some tables every time new config with some changes is apllied.
m
I think this is the right channel. Can you share more info? Which platform, and which evented tables?
j
starting up osqueryi:
Copy code
sudo osqueryi --disable_events=False --flagfile=/private/var/osquery/osquery.flags
Password:
I0722 13:04:26.958304 242097600 init.cpp:343] osquery initialized [version=4.3.0]
I0722 13:04:26.959514 242097600 extensions.cpp:383] Could not autoload extensions: Failed reading: /var/osquery/extensions.load
I0722 13:04:26.959726 242097600 rocksdb.cpp:131] Opening RocksDB handle: /private/var/osquery/osquery.db
I0722 13:04:27.010406 242097600 dispatcher.cpp:77] Adding new service: ExtensionWatcher (0x7ff3bd50cce8) to thread: 0x70000edcd000 (0x7ff3bd50cc10) in process 32664
I0722 13:04:27.010525 242097600 dispatcher.cpp:77] Adding new service: ExtensionRunnerCore (0x7ff3bd50a7a8) to thread: 0x70000ee50000 (0x7ff3bd50ceb0) in process 32664
I0722 13:04:27.010617 242097600 auto_constructed_tables.cpp:96] Removing stale ATC entries
I0722 13:04:27.010813 249888768 interface.cpp:268] Extension manager service starting: /Users/tyburczyk/.osquery/shell.em
I0722 13:04:27.011708 242097600 dispatcher.cpp:77] Adding new service: ConfigRefreshRunner (0x7ff3bd711cf8) to thread: 0x70000eed3000 (0x7ff3bd711080) in process 32664
I0722 13:04:27.012864 242097600 tls.cpp:253] TLS/HTTPS POST request to URI: <https://127.0.0.1:9000/config>
{"node_key":"b90e07e3-6759-48c0-9ad9-e2ff5293ce30"}
{
  "file_paths": {
    "binaries": [
      "/usr/bin/%%", 
      "/usr/sbin/%%", 
      "/bin/%%", 
      "/sbin/%%", 
      "/usr/local/bin/%%", 
      "/usr/local/sbin/%%", 
      "/opt/bin/%%", 
      "/opt/sbin/%%"
    ], 
    "configuration": [
      "/etc/%%"
    ]
  }, 
  "node_invalid": false, 
  "options": {
    "custom_plgx_EnableSSL": "false", 
    "custom_plgx_EnableWatcher": "true", 
    "disable_watchdog": true, 
    "host_identifier": "uuid", 
    "logger_tls_compress": true, 
    "schedule_splay_percent": 10
  }, 
  "packs": {}, 
  "schedule": {
    "test_query": {
      "description": "", 
      "id": 105, 
      "interval": 60, 
      "platform": "all", 
      "query": "select * from socket_events where remote_port=1234;", 
      "removed": false, 
      "shard": 100, 
      "snapshot": false, 
      "tags": [
        "apt29_test"
      ], 
      "value": "", 
      "version": ""
    }
  }
}

I0722 13:04:27.192129 242097600 dispatcher.cpp:77] Adding new service: TLSLogForwarder (0x7ff3bd60c0c8) to thread: 0x70000efd9000 (0x7ff3bd611d10) in process 32664
I0722 13:04:27.192270 242097600 system.cpp:294] Using host identifier: C7B4C7ED-0DF6-569F-9E7A-10DEC3827CB5
I0722 13:04:27.194416 242097600 events.cpp:863] Event publisher not enabled: scnetwork: Publisher not used
I0722 13:04:27.194458 242097600 events.cpp:863] Event publisher not enabled: event_tapping: Publisher disabled via configuration
I0722 13:04:27.230384 242097600 file_events.cpp:67] Added file event listener to: /usr/bin/**
I0722 13:04:27.230437 242097600 file_events.cpp:67] Added file event listener to: /usr/sbin/**
I0722 13:04:27.230453 242097600 file_events.cpp:67] Added file event listener to: /bin/**
I0722 13:04:27.230466 242097600 file_events.cpp:67] Added file event listener to: /sbin/**
I0722 13:04:27.230479 242097600 file_events.cpp:67] Added file event listener to: /usr/local/bin/**
I0722 13:04:27.230490 242097600 file_events.cpp:67] Added file event listener to: /usr/local/sbin/**
I0722 13:04:27.230502 242097600 file_events.cpp:67] Added file event listener to: /opt/bin/**
I0722 13:04:27.230513 242097600 file_events.cpp:67] Added file event listener to: /opt/sbin/**
I0722 13:04:27.230526 242097600 file_events.cpp:67] Added file event listener to: /private/etc/**
Using a virtual database. Need help, type '.help'
I0722 13:04:27.230753 252035072 events.cpp:784] Starting event publisher run loop: diskarbitration
I0722 13:04:27.230782 253108224 events.cpp:784] Starting event publisher run loop: iokit
I0722 13:04:27.230784 252571648 events.cpp:784] Starting event publisher run loop: fsevents
I0722 13:04:27.230792 253644800 events.cpp:784] Starting event publisher run loop: openbsm
configuration:
Copy code
osquery> .show
osquery - being built, with love, at Facebook
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
osquery 4.3.0
using SQLite 3.31.1

General settings:
     Flagfile: /private/var/osquery/osquery.flags
       Config: tls (127.0.0.1:9000/config)
       Logger: filesystem,tls
  Distributed: tls
     Database: rocksdb (/private/var/osquery/osquery.db)
   Extensions: core
       Socket: /Users/tyburczyk/.osquery/shell.em

Shell settings:
         echo: off
      headers: on
         mode: pretty
    nullvalue: ""
       output: stdout
    separator: "|"
        width: 

Non-default flags/options:
I0722 13:04:29.993309 242097600 sqlite_util.cpp:267] DBManager contention: opening transient SQLite database
I0722 13:04:30.020293 242097600 sqlite_util.cpp:267] DBManager contention: opening transient SQLite database
  allow_unsafe: true
  audit_allow_sockets: true
  carver_block_size: 300000
  carver_continue_endpoint: /upload_blocks
  carver_disable_function: false
  carver_start_endpoint: /start_uploads
  config_plugin: tls
  config_refresh: 300
  config_tls_endpoint: /config
  config_tls_max_attempts: 5
  custom_plgx_EnableSSL: false
  custom_plgx_EnableWatcher: true
  database_path: /private/var/osquery/osquery.db
  disable_audit: false
  disable_carver: false
  disable_distributed: false
  disable_watchdog: true
  distributed_interval: 15
  distributed_tls_max_attempts: 5
  distributed_tls_read_endpoint: /distributed/read
  distributed_tls_write_endpoint: /distributed/write
  enroll_secret_path: /private/var/osquery/secret.txt
  enroll_tls_endpoint: /enroll
  events_max: 2500
  extensions_socket: /Users/tyburczyk/.osquery/shell.em
  hash_delay: 0
  host_identifier: uuid
  logger_path: /private/var/log/
  logger_plugin: filesystem,tls
  logger_tls_compress: true
  logger_tls_endpoint: /log
  logger_tls_period: 30
  pack_delimiter: /
  pidfile: /private/var/osquery/osquery.pid
  stderrthreshold: 3
  tls_dump: true
  tls_hostname: 127.0.0.1:9000
  tls_server_certs: /private/var/osquery/certificate.crt
  verbose: true
  watchdog_level: -1
and publisher/subscriber after loading initial config:
Copy code
osquery> select * from osquery_events;
+-------------------------+-----------------+------------+---------------+--------+-----------+--------+
| name                    | publisher       | type       | subscriptions | events | refreshes | active |
+-------------------------+-----------------+------------+---------------+--------+-----------+--------+
| diskarbitration         | diskarbitration | publisher  | 1             | 9      | 0         | 1      |
| event_tapping           | event_tapping   | publisher  | 1             | 0      | 0         | 0      |
| fsevents                | fsevents        | publisher  | 9             | 0      | 0         | 1      |
| iokit                   | iokit           | publisher  | 1             | 0      | 0         | 1      |
| openbsm                 | openbsm         | publisher  | 11            | 1082   | 0         | 1      |
| scnetwork               | scnetwork       | publisher  | 0             | 0      | 0         | 0      |
| disk_events             | diskarbitration | subscriber | 1             | 9      | 0         | 1      |
| file_events             | fsevents        | subscriber | 9             | 0      | 0         | 1      |
| hardware_events         | iokit           | subscriber | 1             | 0      | 0         | 1      |
| process_events          | openbsm         | subscriber | 8             | 0      | 0         | 1      |
| socket_events           | openbsm         | subscriber | 2             | 4      | 0         | 1      |
| user_events             | openbsm         | subscriber | 1             | 0      | 0         | 1      |
| user_interaction_events | event_tapping   | subscriber | 1             | 0      | 0         | 1      |
| yara_events             | fsevents        | subscriber | 0             | 0      | 0         | 1      |
+-------------------------+-----------------+------------+---------------+--------+-----------+--------+
now, I did changes to scheduled queries at the server so the next time config comes as:
Copy code
osquery> I0722 13:09:27.013913 250425344 config.cpp:1214] Refreshing configuration state
I0722 13:09:27.015131 250425344 tls.cpp:253] TLS/HTTPS POST request to URI: <https://127.0.0.1:9000/config>
{"node_key":"b90e07e3-6759-48c0-9ad9-e2ff5293ce30"}
{
  "file_paths": {
    "binaries": [
      "/usr/bin/%%", 
      "/usr/sbin/%%", 
      "/bin/%%", 
      "/sbin/%%", 
      "/usr/local/bin/%%", 
      "/usr/local/sbin/%%", 
      "/opt/bin/%%", 
      "/opt/sbin/%%"
    ], 
    "configuration": [
      "/etc/%%"
    ]
  }, 
  "node_invalid": false, 
  "options": {
    "custom_plgx_EnableSSL": "false", 
    "custom_plgx_EnableWatcher": "true", 
    "disable_watchdog": true, 
    "host_identifier": "uuid", 
    "logger_tls_compress": true, 
    "schedule_splay_percent": 10
  }, 
  "packs": {}, 
  "schedule": {
    "test_query": {
      "description": "", 
      "id": 105, 
      "interval": 60, 
      "platform": "all", 
      "query": "select * from socket_events where remote_port=1235;", 
      "removed": false, 
      "shard": 100, 
      "snapshot": false, 
      "tags": [
        "apt29_test"
      ], 
      "value": "", 
      "version": ""
    }
  }
}

I0722 13:09:27.162900 250425344 file_events.cpp:67] Added file event listener to: /usr/bin/**
I0722 13:09:27.162940 250425344 file_events.cpp:67] Added file event listener to: /usr/sbin/**
I0722 13:09:27.162955 250425344 file_events.cpp:67] Added file event listener to: /bin/**
I0722 13:09:27.162968 250425344 file_events.cpp:67] Added file event listener to: /sbin/**
I0722 13:09:27.162981 250425344 file_events.cpp:67] Added file event listener to: /usr/local/bin/**
I0722 13:09:27.162992 250425344 file_events.cpp:67] Added file event listener to: /usr/local/sbin/**
I0722 13:09:27.163004 250425344 file_events.cpp:67] Added file event listener to: /opt/bin/**
I0722 13:09:27.163015 250425344 file_events.cpp:67] Added file event listener to: /opt/sbin/**
I0722 13:09:27.163028 250425344 file_events.cpp:67] Added file event listener to: /private/etc/**
I0722 13:09:27.164523 250425344 config.cpp:899] Calling configure for logger filesystem
I0722 13:09:27.164557 250425344 config.cpp:899] Calling configure for logger tls
(just a change of port in scheduled query)
after this you can see subscribers added again, without removing of previous subscriptions (this is a bit of the guess based on numbers):
Copy code
osquery> select * from osquery_events;
+-------------------------+-----------------+------------+---------------+--------+-----------+--------+
| name                    | publisher       | type       | subscriptions | events | refreshes | active |
+-------------------------+-----------------+------------+---------------+--------+-----------+--------+
| diskarbitration         | diskarbitration | publisher  | 1             | 9      | 0         | 1      |
| event_tapping           | event_tapping   | publisher  | 2             | 0      | 0         | 0      |
| fsevents                | fsevents        | publisher  | 9             | 0      | 1         | 1      |
| iokit                   | iokit           | publisher  | 1             | 0      | 0         | 1      |
| openbsm                 | openbsm         | publisher  | 22            | 296389 | 0         | 1      |
| scnetwork               | scnetwork       | publisher  | 0             | 0      | 0         | 0      |
| disk_events             | diskarbitration | subscriber | 1             | 9      | 0         | 1      |
| file_events             | fsevents        | subscriber | 9             | 0      | 0         | 1      |
| hardware_events         | iokit           | subscriber | 1             | 0      | 0         | 1      |
| process_events          | openbsm         | subscriber | 16            | 3      | 0         | 1      |
| socket_events           | openbsm         | subscriber | 4             | 100    | 0         | 1      |
| user_events             | openbsm         | subscriber | 2             | 0      | 0         | 1      |
| user_interaction_events | event_tapping   | subscriber | 2             | 0      | 0         | 1      |
| yara_events             | fsevents        | subscriber | 0             | 0      | 0         | 1      |
+-------------------------+-----------------+------------+---------------+--------+-----------+--------+
so for the following number has doubled: • event_taping • openbsm • process_events • socket_events • user_events • user_interaction_events for following cannot tell: • scnetwork • yara_events
I believe this is why I am observing duplicated events later on. After issuing one 
curl <http://portquiz.net:1234|portquiz.net:1234>
I get 2 events with different eids but the same timestamp:
Copy code
osquery> select *,eid from socket_events where remote_port=1234;
+---------+-------+---------------+----+------+---------+--------+---------------+----------------+------------+-------------+------------+--------+------------+
| action  | pid   | path          | fd | auid | success | family | local_address | remote_address | local_port | remote_port | time       | uptime | eid        |
+---------+-------+---------------+----+------+---------+--------+---------------+----------------+------------+-------------+------------+--------+------------+
| connect | 33004 | /usr/bin/curl | 5  | 501  | 0       | 2      | 0             | 52.47.209.216  | 0          | 1234        | 1595416715 | 429288 | 0000001391 |
| connect | 33004 | /usr/bin/curl | 5  | 501  | 0       | 2      | 0             | 52.47.209.216  | 0          | 1234        | 1595416715 | 429288 | 0000001392 |
+---------+-------+---------------+----+------+---------+--------+---------------+----------------+------------+-------------+------------+--------+------------+
We were not able to reproduce this behaviour on linux, only macOS.
Shell I provide additional details?
Also, probably important. After restarting all numbers are back to original values.
m
Thanks Jacek. These are good details, but since I don't know the solution maybe I'll refer it to the channel outside this thread to reply, otherwise, we may have to open an issue on Github about it
👍 1
9 Views
Open in Slack
PreviousNext
Powered by