Files Open with Write Permissions Trigger "UPDATED" Action When No Changes Are Made

[ricardobruno]

Hello Everyone,
It's a special day! After years of being an Open Source user, today is the first time I'm posting a public GitHub issue to an Open Source project. I'm still figuring out how to best contribute, so please be nice! ;-)

Issue Summary:
In the Linux Operating System, if a file is open with a file descriptor that has write permissions, upon closing that file, an UPDATED action event is triggered in osquery, even though there were no changes made to the original file. This issue can generate numerous false positive osquery UPDATED alerts in certain environments.

Detailed Description:
When a file is opened with write permissions, and closed, the current behavior of inotify in the Linux Kernel is to trigger an IN_CLOSE_WRITE event. That occurs even when no changes are made to that file.
The current behavior of osquery inotify.cpp / kMaskActions osquery inotify.cpp / kMaskActions is to map theseIN_CLOSE_WRITE events to UPDATED, relying on the IN_CLOSE_WRITE event as if it was an authoritative indicator of file changes.

The Linux Kernel Header for inotify describes the IN_CLOSE_WRITE event as writable file was closed, but it doesn't go as far as saying that the file was modified:

#define IN_CLOSE_WRITE		0x00000008	/* Writtable file was closed */

This behavior results in numerous false positive events, as applications open files with write permissions, and close these files without any modification.
I'm not sure how to best solve this, so I'm posting here hoping to get some smart eyes on it.
Though I have limited expertise in this codebase, I would be happy to help further review, and validate this issue, and hopefully come up with a solution.

Keywords:

duplicate events
inaccurate UPDATE events
inotify
kMaskActions
IN_MODIFY
IN_CLOSE_WRITE

Tested osquery Version:

$ rpm -q osquery
osquery-2.6.1-1.linux.x86_64

osquery> select version,build_platform,build_distro  from time, osquery_info;
+---------+----------------+--------------+
| version | build_platform | build_distro |
+---------+----------------+--------------+
| 2.6.1   | ubuntu         | xenial       |
+---------+----------------+--------------+

Operating System Information:

$ cat /etc/redhat-release
CentOS Linux release 7.3.1611 (Core)

$ cat /proc/version
Linux version 3.10.0-514.26.2.el7.x86_64 ([email protected]) (gcc version 4.8.5 20150623 (Red Hat 4.8.5-11) (GCC) ) #1 SMP Tue Jul 4 15:04:05 UTC 2017

Script to Reproduce Events:
(*) Requires the pyinotify module: (pip install pyinotify)

#!/usr/bin/env python
import os
import time
import pyinotify


def get_inotify_events(notifier):
    """Retrieves acumulated inotify watched events"""
    assert notifier._timeout is not None, 'Notifier must have a short timeout'
    notifier.process_events()
    # loop in case more events show up while processing
    while notifier.check_events():
        notifier.read_events()
        notifier.process_events()


def main():
    """ Main Program Handler """

    # Sample file to be watched
    filename = "/tmp/testopenrw-nowrites.txt"
    file = open(filename, "a+")
    file.close()

    # Creates New Instance of WatchManager to Store Events Being Watched
    watch_manager = pyinotify.WatchManager()

    # Add a new watch specific to FILENAME for ALL_EVENTS
    watch_manager.add_watch(filename, pyinotify.ALL_EVENTS)

    # Associate WatchManager with a Notifier to report and process events
    notifier = pyinotify.Notifier(watch_manager, timeout=3)

    number_of_attempts = 5
    print("Opening %s with RW, and closing without changes %s times..." % (
                                             filename, number_of_attempts))
    for count in range(number_of_attempts):
        print ("\nOpening file(rw), closing file(no writes) #%s" % (count+1))
        file = open(filename, "r+")
        stattest = os.stat(filename)
        print("%s" % (stattest))
        file.close()
        time.sleep(1)
        get_inotify_events(notifier)


if __name__ == "__main__":
    main()

Script Output:

 # python testopenrw-nowrites.py
Opening /tmp/testopenrw-nowrites.txt with RW, and closing without changes 5 times...

Opening file(rw), closing file(no writes) #1
posix.stat_result(st_mode=33188, st_ino=6928449, st_dev=51713L, st_nlink=1, st_uid=0, st_gid=0, st_size=0, st_atime=1510347872, st_mtime=1510347872, st_ctime=1510347872)
<Event dir=False mask=0x20 maskname=IN_OPEN name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x8 maskname=IN_CLOSE_WRITE name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x20 maskname=IN_OPEN name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x10 maskname=IN_CLOSE_NOWRITE name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >

Opening file(rw), closing file(no writes) #2
posix.stat_result(st_mode=33188, st_ino=6928449, st_dev=51713L, st_nlink=1, st_uid=0, st_gid=0, st_size=0, st_atime=1510347872, st_mtime=1510347872, st_ctime=1510347872)
<Event dir=False mask=0x20 maskname=IN_OPEN name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x8 maskname=IN_CLOSE_WRITE name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x20 maskname=IN_OPEN name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x10 maskname=IN_CLOSE_NOWRITE name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >

Opening file(rw), closing file(no writes) #3
posix.stat_result(st_mode=33188, st_ino=6928449, st_dev=51713L, st_nlink=1, st_uid=0, st_gid=0, st_size=0, st_atime=1510347872, st_mtime=1510347872, st_ctime=1510347872)
<Event dir=False mask=0x20 maskname=IN_OPEN name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x8 maskname=IN_CLOSE_WRITE name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x20 maskname=IN_OPEN name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x10 maskname=IN_CLOSE_NOWRITE name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >

Opening file(rw), closing file(no writes) #4
posix.stat_result(st_mode=33188, st_ino=6928449, st_dev=51713L, st_nlink=1, st_uid=0, st_gid=0, st_size=0, st_atime=1510347872, st_mtime=1510347872, st_ctime=1510347872)
<Event dir=False mask=0x20 maskname=IN_OPEN name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x8 maskname=IN_CLOSE_WRITE name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x20 maskname=IN_OPEN name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x10 maskname=IN_CLOSE_NOWRITE name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >

Opening file(rw), closing file(no writes) #5
posix.stat_result(st_mode=33188, st_ino=6928449, st_dev=51713L, st_nlink=1, st_uid=0, st_gid=0, st_size=0, st_atime=1510347872, st_mtime=1510347872, st_ctime=1510347872)
<Event dir=False mask=0x20 maskname=IN_OPEN name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x8 maskname=IN_CLOSE_WRITE name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x20 maskname=IN_OPEN name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >
<Event dir=False mask=0x10 maskname=IN_CLOSE_NOWRITE name='' path=/tmp/testopenrw-nowrites.txt pathname=/tmp/testopenrw-nowrites.txt wd=1 >

Sample OS Query logs from /var/log/osquery/osqueryd.results.log:

{
  "name": "file_events",
  "hostIdentifier": "ip-10-150-145-77",
  "calendarTime": "Fri Nov 10 21:05:10 2017 UTC",
  "unixTime": "1510347910",
  "epoch": "0",
  "decorations": {
    "host_uuid": "---redacted host_uuid---",
    "username": "---redacted username---"
  },
  "columns": {
    "action": "CREATED",
    "atime": "1510347872",
    "category": "tmp",
    "ctime": "1510347872",
    "gid": "0",
    "hashed": "1",
    "inode": "6928449",
    "md5": "d41d8cd98f00b204e9800998ecf8427e",
    "mode": "0644",
    "mtime": "1510347872",
    "sha1": "da39a3ee5e6b4b0d3255bfef95601890afd80709",
    "sha256": "e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855",
    "size": "0",
    "target_path": "\/tmp\/testopenrw-nowrites.txt",
    "time": "1510347872",
    "transaction_id": "0",
    "uid": "0"
  },
  "action": "added"
} {
  "name": "file_events",
  "hostIdentifier": "ip-10-150-145-77",
  "calendarTime": "Fri Nov 10 21:05:10 2017 UTC",
  "unixTime": "1510347910",
  "epoch": "0",
  "decorations": {
    "host_uuid": "---redacted host_uuid---",
    "username": "---redacted username---"
  },
  "columns": {
    "action": "UPDATED",
    "atime": "1510347872",
    "category": "tmp",
    "ctime": "1510347872",
    "gid": "0",
    "hashed": "1",
    "inode": "6928449",
    "md5": "d41d8cd98f00b204e9800998ecf8427e",
    "mode": "0644",
    "mtime": "1510347872",
    "sha1": "da39a3ee5e6b4b0d3255bfef95601890afd80709",
    "sha256": "e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855",
    "size": "0",
    "target_path": "\/tmp\/testopenrw-nowrites.txt",
    "time": "1510347872",
    "transaction_id": "0",
    "uid": "0"
  },
  "action": "added"
} {
  "name": "file_events",
  "hostIdentifier": "ip-10-150-145-77",
  "calendarTime": "Fri Nov 10 21:05:10 2017 UTC",
  "unixTime": "1510347910",
  "epoch": "0",
  "decorations": {
    "host_uuid": "---redacted host_uuid---",
    "username": "---redacted username---"
  },
  "columns": {
    "action": "UPDATED",
    "atime": "1510347872",
    "category": "tmp",
    "ctime": "1510347872",
    "gid": "0",
    "hashed": "1",
    "inode": "6928449",
    "md5": "d41d8cd98f00b204e9800998ecf8427e",
    "mode": "0644",
    "mtime": "1510347872",
    "sha1": "da39a3ee5e6b4b0d3255bfef95601890afd80709",
    "sha256": "e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855",
    "size": "0",
    "target_path": "\/tmp\/testopenrw-nowrites.txt",
    "time": "1510347873",
    "transaction_id": "0",
    "uid": "0"
  },
  "action": "added"
} {
  "name": "file_events",
  "hostIdentifier": "ip-10-150-145-77",
  "calendarTime": "Fri Nov 10 21:05:10 2017 UTC",
  "unixTime": "1510347910",
  "epoch": "0",
  "decorations": {
    "host_uuid": "---redacted host_uuid---",
    "username": "---redacted username---"
  },
  "columns": {
    "action": "UPDATED",
    "atime": "1510347872",
    "category": "tmp",
    "ctime": "1510347872",
    "gid": "0",
    "hashed": "1",
    "inode": "6928449",
    "md5": "d41d8cd98f00b204e9800998ecf8427e",
    "mode": "0644",
    "mtime": "1510347872",
    "sha1": "da39a3ee5e6b4b0d3255bfef95601890afd80709",
    "sha256": "e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855",
    "size": "0",
    "target_path": "\/tmp\/testopenrw-nowrites.txt",
    "time": "1510347873",
    "transaction_id": "0",
    "uid": "0"
  },
  "action": "added"
} {
  "name": "file_events",
  "hostIdentifier": "ip-10-150-145-77",
  "calendarTime": "Fri Nov 10 21:05:10 2017 UTC",
  "unixTime": "1510347910",
  "epoch": "0",
  "decorations": {
    "host_uuid": "---redacted host_uuid---",
    "username": "---redacted username---"
  },
  "columns": {
    "action": "UPDATED",
    "atime": "1510347872",
    "category": "tmp",
    "ctime": "1510347872",
    "gid": "0",
    "hashed": "1",
    "inode": "6928449",
    "md5": "d41d8cd98f00b204e9800998ecf8427e",
    "mode": "0644",
    "mtime": "1510347872",
    "sha1": "da39a3ee5e6b4b0d3255bfef95601890afd80709",
    "sha256": "e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855",
    "size": "0",
    "target_path": "\/tmp\/testopenrw-nowrites.txt",
    "time": "1510347874",
    "transaction_id": "0",
    "uid": "0"
  },
  "action": "added"
} {
  "name": "file_events",
  "hostIdentifier": "ip-10-150-145-77",
  "calendarTime": "Fri Nov 10 21:05:10 2017 UTC",
  "unixTime": "1510347910",
  "epoch": "0",
  "decorations": {
    "host_uuid": "---redacted host_uuid---",
    "username": "---redacted username---"
  },
  "columns": {
    "action": "UPDATED",
    "atime": "1510347872",
    "category": "tmp",
    "ctime": "1510347872",
    "gid": "0",
    "hashed": "1",
    "inode": "6928449",
    "md5": "d41d8cd98f00b204e9800998ecf8427e",
    "mode": "0644",
    "mtime": "1510347872",
    "sha1": "da39a3ee5e6b4b0d3255bfef95601890afd80709",
    "sha256": "e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855",
    "size": "0",
    "target_path": "\/tmp\/testopenrw-nowrites.txt",
    "time": "1510347875",
    "transaction_id": "0",
    "uid": "0"
  },
  "action": "added"
} {
  "name": "file_events",
  "hostIdentifier": "ip-10-150-145-77",
  "calendarTime": "Fri Nov 10 21:05:10 2017 UTC",
  "unixTime": "1510347910",
  "epoch": "0",
  "decorations": {
    "host_uuid": "---redacted host_uuid---",
    "username": "---redacted username---"
  },
  "columns": {
    "action": "UPDATED",
    "atime": "1510347872",
    "category": "tmp",
    "ctime": "1510347872",
    "gid": "0",
    "hashed": "1",
    "inode": "6928449",
    "md5": "d41d8cd98f00b204e9800998ecf8427e",
    "mode": "0644",
    "mtime": "1510347872",
    "sha1": "da39a3ee5e6b4b0d3255bfef95601890afd80709",
    "sha256": "e3b0c44298fc1c149afbf4c8996fb92427ae41e4649b934ca495991b7852b855",
    "size": "0",
    "target_path": "\/tmp\/testopenrw-nowrites.txt",
    "time": "1510347876",
    "transaction_id": "0",
    "uid": "0"
  },
  "action": "added"
}

Additional Information:
The inotify FAQ goes over why we need to track both IN_MODIFY, and IN_CLOSE_WRITE events.
I don't see any mention in the FAQ that IN_CLOSE_WRITE will also be raised when a writable file is closed without modifications.

Notes / Ideas / Possible Workarounds:

• This seems to be a combination of something bubbling up from the upstream Linux Kernel implementation of inotify, along with osquery's reliance certain assumptions of the inotify behavior.
• On the osquery side, I've seen hundreds of thousands of these UPDATED events, some with completely the same exact message, and others with just the timestamp changed even though no changes were made.
• There may be a workaround in creating a sql query that would minimize the display repeated false positive events.
• Figure out additional logic that would compare a IN_CLOSE_WRITE event with a previous similar event, if any, and determine whether there was an actual change. If there was an actual change the IN_CLOSE_WRITE reference in osquery inotify.cpp / kMaskActions osquery inotify.cpp / kMaskActions would conditionally map to something like UPDATED if a change can be confirmed, or CLOSED if no change was made.