{"action":"opened","issue":{"url":"https://api.github.com/repos/facebook/osquery/issues/1374","labels_url":"https://api.github.com/repos/facebook/osquery/issues/1374/labels{/name}","comments_url":"https://api.github.com/repos/facebook/osquery/issues/1374/comments","events_url":"https://api.github.com/repos/facebook/osquery/issues/1374/events","html_url":"https://github.com/facebook/osquery/issues/1374","id":96659411,"number":1374,"title":"Duplicate events with multiple subscribers","user":{"login":"wxsBSD","id":1394879,"avatar_url":"https://avatars.githubusercontent.com/u/1394879?v=3","gravatar_id":"","url":"https://api.github.com/users/wxsBSD","html_url":"https://github.com/wxsBSD","followers_url":"https://api.github.com/users/wxsBSD/followers","following_url":"https://api.github.com/users/wxsBSD/following{/other_user}","gists_url":"https://api.github.com/users/wxsBSD/gists{/gist_id}","starred_url":"https://api.github.com/users/wxsBSD/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/wxsBSD/subscriptions","organizations_url":"https://api.github.com/users/wxsBSD/orgs","repos_url":"https://api.github.com/users/wxsBSD/repos","events_url":"https://api.github.com/users/wxsBSD/events{/privacy}","received_events_url":"https://api.github.com/users/wxsBSD/received_events","type":"User","site_admin":false},"labels":[],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":0,"created_at":"2015-07-22T20:44:30Z","updated_at":"2015-07-22T20:44:30Z","closed_at":null,"body":"I've stumbled upon something while working on a minor addition to the YARA stuff in osquery. It is a bit cumbersome to explain but it appears that events fire multiple times in some cases. I'll provide the configs and other necessary pieces to replicate this...\r\n\r\nHere's a config which watches a directory for changes which are reflected in ```file_events``` table.\r\n\r\n```\r\nwxs@psh osquery % cat bar.config\r\n{\r\n  // Paths to watch for filesystem events\r\n  \"file_paths\": {\r\n    \"tmp\": [ \"/Users/wxs/tmp/%%\" ]\r\n  }\r\n}\r\n```\r\n\r\nHere's the config in action. While ```osqueryi``` is running I execute ```cp /bin/ls ~/tmp```.\r\n\r\n```\r\nwxs@psh osquery % build/debug_darwin/osquery/osqueryi --verbose --config_path=bar.config\r\nI0722 15:31:13.625607 1985979136 init.cpp:200] osquery initialized [version=1.4.5-341-g5f4d547]\r\nI0722 15:31:13.625860 1985979136 extensions.cpp:178] Could not autoload modules: Failed reading: /etc/osquery/modules.load\r\nI0722 15:31:13.626055 1985979136 db_handle.cpp:120] Opening RocksDB handle: /Users/wxs/.osquery/shell.db\r\nI0722 15:31:13.629534 117751808 interface.cpp:220] Extension manager service starting: /Users/wxs/.osquery/shell.em\r\nI0722 15:31:13.630033 1985979136 config.cpp:72] Updating config with source: bar.config\r\nI0722 15:31:13.631096 1985979136 file_events.cpp:58] Added listener to: /Users/wxs/tmp/**\r\nI0722 15:31:13.631400 122531840 events.cpp:502] Starting event publisher run loop: diskarbitration\r\nI0722 15:31:13.631407 123068416 events.cpp:502] Starting event publisher run loop: fsevents\r\nI0722 15:31:13.631424 123604992 events.cpp:502] Starting event publisher run loop: iokit_hid\r\nI0722 15:31:13.631453 124141568 events.cpp:502] Starting event publisher run loop: kernel\r\nI0722 15:31:13.631481 124678144 events.cpp:502] Starting event publisher run loop: scnetwork\r\nI0722 15:31:13.655782 124141568 events.cpp:512] Event publisher kernel run loop terminated for reason: No kernel communication.\r\nosquery - being built, with love, at Facebook\r\n\r\nUsing a virtual database. Need help, type '.help'\r\nosquery> I0722 15:31:16.741888 123068416 db_handle.cpp:120] Opening RocksDB handle: /Users/wxs/.osquery/shell.db\r\n\r\nosquery> select * from file_events;\r\nI0722 15:31:21.650671 1985979136 virtual_table.cpp:234] Table file_events row 2 did not include column md5\r\nI0722 15:31:21.650732 1985979136 virtual_table.cpp:234] Table file_events row 2 did not include column sha1\r\nI0722 15:31:21.650750 1985979136 virtual_table.cpp:234] Table file_events row 2 did not include column sha256\r\n+-------------------+----------+---------------------+----------------+----------------------------------+------------------------------------------+------------------------------------------------------------------+------------+\r\n| target_path       | category | action              | transaction_id | md5                              | sha1                                     | sha256                                                           | time       |\r\n+-------------------+----------+---------------------+----------------+----------------------------------+------------------------------------------+------------------------------------------------------------------+------------+\r\n| /Users/wxs/tmp/ls | tmp      | CREATED             | 3286808        | 33c72b9531677c467d2330c35e18fb5a | f378ba2aa7f90378a9cae9b1546bb2d21b2b6666 | 482c752811c90d450fe46c04aa29ad588bbd1c03d79fc16cf6ef0a7175bd5615 | 1437593476 |\r\n| /Users/wxs/tmp/ls | tmp      | UPDATED             | 3286808        | 33c72b9531677c467d2330c35e18fb5a | f378ba2aa7f90378a9cae9b1546bb2d21b2b6666 | 482c752811c90d450fe46c04aa29ad588bbd1c03d79fc16cf6ef0a7175bd5615 | 1437593476 |\r\n| /Users/wxs/tmp/ls | tmp      | ATTRIBUTES_MODIFIED | 3286808        |                                  |                                          |                                                                  | 1437593476 |\r\n+-------------------+----------+---------------------+----------------+----------------------------------+------------------------------------------+------------------------------------------------------------------+------------+\r\nosquery>\r\n```\r\n\r\nLooks pretty good so far. Here is the config which watches for both ```file_events``` and ```yara_events```.\r\n\r\n```\r\nwxs@psh osquery % cat foo.config\r\n{\r\n  // Description of the YARA feature.\r\n  \"yara\": {\r\n    \"signatures\": {\r\n      // Each key is an arbitrary group name to give the signatures listed\r\n      \"sig_group_1\": [ \"/Users/wxs/Documents/dev/osquery/ls.sig\" ]\r\n    },\r\n    \"file_paths\": {\r\n      // Each key is a key from file_paths\r\n      // The value is a list of signature groups to run when an event fires\r\n      // These will be watched for and scanned when the event framework\r\n      // fire off an event to yara_events table\r\n      \"tmp\": [ \"sig_group_1\" ]\r\n    }\r\n  },\r\n\r\n  // Paths to watch for filesystem events\r\n  \"file_paths\": {\r\n    \"tmp\": [ \"/Users/wxs/tmp/%%\" ]\r\n  }\r\n}\r\n```\r\n\r\nAnd just to make sure it can be replicated, here is the contents of ```ls.sig```.\r\n\r\n```\r\nwxs@psh osquery % cat ls.sig\r\nrule macho: test {\r\n  strings:\r\n    $a = \"usage: ls\"\r\n    $b = \"humanize_number\"\r\n  condition:\r\n    all of them\r\n}\r\n```\r\n\r\nIn between runs I am cleaning out ```~/tmp``` and ```~/.osquery```. Here is the problem:\r\n\r\n```\r\nwxs@psh osquery % build/debug_darwin/osquery/osqueryi --verbose --config_path=foo.config\r\nI0722 15:33:20.618417 1985979136 init.cpp:200] osquery initialized [version=1.4.5-341-g5f4d547]\r\nI0722 15:33:20.618654 1985979136 extensions.cpp:178] Could not autoload modules: Failed reading: /etc/osquery/modules.load\r\nI0722 15:33:20.618779 1985979136 db_handle.cpp:120] Opening RocksDB handle: /Users/wxs/.osquery/shell.db\r\nI0722 15:33:20.624413 90705920 interface.cpp:220] Extension manager service starting: /Users/wxs/.osquery/shell.em\r\nI0722 15:33:20.624763 1985979136 config.cpp:72] Updating config with source: foo.config\r\nI0722 15:33:20.627542 1985979136 yara_utils.cpp:239] Compiling YARA signature group: sig_group_1\r\nI0722 15:33:20.627774 1985979136 yara_utils.cpp:127] Loading /Users/wxs/Documents/dev/osquery/ls.sig\r\nI0722 15:33:20.628468 1985979136 file_events.cpp:58] Added listener to: /Users/wxs/tmp/**\r\nI0722 15:33:20.628681 1985979136 yara_events.cpp:93] Added YARA listener to: /Users/wxs/tmp/**\r\nI0722 15:33:20.628824 95485952 events.cpp:502] Starting event publisher run loop: diskarbitration\r\nI0722 15:33:20.628988 96022528 events.cpp:502] Starting event publisher run loop: fsevents\r\nI0722 15:33:20.630532 105922560 events.cpp:502] Starting event publisher run loop: iokit_hid\r\nI0722 15:33:20.631191 106459136 events.cpp:502] Starting event publisher run loop: kernel\r\nI0722 15:33:20.632177 106995712 events.cpp:502] Starting event publisher run loop: scnetwork\r\nI0722 15:33:20.655933 106459136 events.cpp:512] Event publisher kernel run loop terminated for reason: No kernel communication.\r\nosquery - being built, with love, at Facebook\r\n\r\nUsing a virtual database. Need help, type '.help'\r\nosquery> I0722 15:33:24.050813 96022528 db_handle.cpp:120] Opening RocksDB handle: /Users/wxs/.osquery/shell.db\r\n\r\nosquery> select * from file_events;\r\nI0722 15:33:31.840809 1985979136 virtual_table.cpp:234] Table file_events row 1 did not include column md5\r\nI0722 15:33:31.840862 1985979136 virtual_table.cpp:234] Table file_events row 1 did not include column sha1\r\nI0722 15:33:31.840880 1985979136 virtual_table.cpp:234] Table file_events row 1 did not include column sha256\r\nI0722 15:33:31.840932 1985979136 virtual_table.cpp:234] Table file_events row 3 did not include column md5\r\nI0722 15:33:31.840951 1985979136 virtual_table.cpp:234] Table file_events row 3 did not include column sha1\r\nI0722 15:33:31.840968 1985979136 virtual_table.cpp:234] Table file_events row 3 did not include column sha256\r\nI0722 15:33:31.840998 1985979136 virtual_table.cpp:234] Table file_events row 4 did not include column md5\r\nI0722 15:33:31.841017 1985979136 virtual_table.cpp:234] Table file_events row 4 did not include column sha1\r\nI0722 15:33:31.841042 1985979136 virtual_table.cpp:234] Table file_events row 4 did not include column sha256\r\nI0722 15:33:31.841070 1985979136 virtual_table.cpp:234] Table file_events row 5 did not include column md5\r\nI0722 15:33:31.841087 1985979136 virtual_table.cpp:234] Table file_events row 5 did not include column sha1\r\nI0722 15:33:31.841104 1985979136 virtual_table.cpp:234] Table file_events row 5 did not include column sha256\r\n+-------------------+----------+---------------------+----------------+----------------------------------+------------------------------------------+------------------------------------------------------------------+------------+\r\n| target_path       | category | action              | transaction_id | md5                              | sha1                                     | sha256                                                           | time       |\r\n+-------------------+----------+---------------------+----------------+----------------------------------+------------------------------------------+------------------------------------------------------------------+------------+\r\n| /Users/wxs/tmp/ls | tmp      | CREATED             | 3288357        | 33c72b9531677c467d2330c35e18fb5a | f378ba2aa7f90378a9cae9b1546bb2d21b2b6666 | 482c752811c90d450fe46c04aa29ad588bbd1c03d79fc16cf6ef0a7175bd5615 | 1437593603 |\r\n| /Users/wxs/tmp/ls | tmp      | CREATED             | 3288357        |                                  |                                          |                                                                  | 1437593603 |\r\n| /Users/wxs/tmp/ls | tmp      | UPDATED             | 3288357        | 33c72b9531677c467d2330c35e18fb5a | f378ba2aa7f90378a9cae9b1546bb2d21b2b6666 | 482c752811c90d450fe46c04aa29ad588bbd1c03d79fc16cf6ef0a7175bd5615 | 1437593603 |\r\n| /Users/wxs/tmp/ls | tmp      | UPDATED             | 3288357        |                                  |                                          |                                                                  | 1437593603 |\r\n| /Users/wxs/tmp/ls | tmp      | ATTRIBUTES_MODIFIED | 3288357        |                                  |                                          |                                                                  | 1437593603 |\r\n| /Users/wxs/tmp/ls | tmp      | ATTRIBUTES_MODIFIED | 3288357        |                                  |                                          |                                                                  | 1437593603 |\r\n+-------------------+----------+---------------------+----------------+----------------------------------+------------------------------------------+------------------------------------------------------------------+------------+\r\nosquery> select * from yara_events;\r\nI0722 15:33:40.010917 1985979136 virtual_table.cpp:234] Table yara_events row 0 did not include column matches\r\nI0722 15:33:40.010972 1985979136 virtual_table.cpp:234] Table yara_events row 0 did not include column count\r\nI0722 15:33:40.011032 1985979136 virtual_table.cpp:234] Table yara_events row 2 did not include column matches\r\nI0722 15:33:40.011059 1985979136 virtual_table.cpp:234] Table yara_events row 2 did not include column count\r\nI0722 15:33:40.011111 1985979136 virtual_table.cpp:234] Table yara_events row 4 did not include column matches\r\nI0722 15:33:40.011134 1985979136 virtual_table.cpp:234] Table yara_events row 4 did not include column count\r\nI0722 15:33:40.017235 1985979136 virtual_table.cpp:134] Error casting count () to INTEGER\r\nI0722 15:33:40.017390 1985979136 virtual_table.cpp:134] Error casting count () to INTEGER\r\nI0722 15:33:40.017479 1985979136 virtual_table.cpp:134] Error casting count () to INTEGER\r\n+-------------------+----------+---------------------+----------------+---------+-------+------------+\r\n| target_path       | category | action              | transaction_id | matches | count | time       |\r\n+-------------------+----------+---------------------+----------------+---------+-------+------------+\r\n| /Users/wxs/tmp/ls | tmp      | CREATED             | 3288357        |         | -1    | 1437593603 |\r\n| /Users/wxs/tmp/ls | tmp      | CREATED             | 3288357        | macho   | 1     | 1437593603 |\r\n| /Users/wxs/tmp/ls | tmp      | UPDATED             | 3288357        |         | -1    | 1437593603 |\r\n| /Users/wxs/tmp/ls | tmp      | UPDATED             | 3288357        | macho   | 1     | 1437593603 |\r\n| /Users/wxs/tmp/ls | tmp      | ATTRIBUTES_MODIFIED | 3288357        |         | -1    | 1437593603 |\r\n| /Users/wxs/tmp/ls | tmp      | ATTRIBUTES_MODIFIED | 3288357        | macho   | 1     | 1437593603 |\r\n+-------------------+----------+---------------------+----------------+---------+-------+------------+\r\nosquery>\r\n```\r\n\r\nLooks like the events are handled twice? It appears that when a callback call calls ```add()``` it is added to both tables?"}}