Title
#general
j

Jacek

07/21/2020, 10:19 AM
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.
Mike Myers

Mike Myers

07/21/2020, 4:48 PM
I think this is the right channel. Can you share more info? Which platform, and which evented tables?
j

Jacek

07/22/2020, 11:09 AM
starting up osqueryi:
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
11:09 AM
configuration:
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
11:10 AM
and publisher/subscriber after loading initial config:
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      |
+-------------------------+-----------------+------------+---------------+--------+-----------+--------+
11:12 AM
now, I did changes to scheduled queries at the server so the next time config comes as:
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)
11:13 AM
after this you can see subscribers added again, without removing of previous subscriptions (this is a bit of the guess based on numbers):
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      |
+-------------------------+-----------------+------------+---------------+--------+-----------+--------+
11:17 AM
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
11:20 AM
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:
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 |
+---------+-------+---------------+----+------+---------+--------+---------------+----------------+------------+-------------+------------+--------+------------+
11:21 AM
We were not able to reproduce this behaviour on linux, only macOS.
11:21 AM
Shell I provide additional details?
8:17 AM
Also, probably important. After restarting all numbers are back to original values.
Mike Myers

Mike Myers

07/23/2020, 6:51 PM
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