how come osx kernel get so many times of file operations

Question

I create a file in userspace(using touch command), I am expecting to see only one OPEN and one CLOSE file operations, however, I get 2 OPEN and 3 CLOSE operations from kernel notification. the operations sequence is like this: open --> close --> open --> close ---> close.... can anybody give me some hints about this? thanks in advance.

Answer 1

Kauth vnode and fileop listeners have been working well for me. If you are receiving event notifications that don't make sense to you, I suggest placing a breakpoint in your kauth listener callback using the kernel debugger and looking at the backtrace. The xnu source code is available, so you should be able to work out from that and the backtrace why you are receiving the notification in question.

I know that you can get extra close notifications if there are multiple handles to a file. So if you open the file, dup() the file descriptor, then close both handles, you'll get one open and 2 closes. That's just how it is, I'm afraid. There's no public kernel API for determining if a process has a remaining handle on a particular file.

As for why you are receiving 2 open notifications - it could be to do with the way touch is written, or something to do with the shell. Normally an open notification really does correspond to an open() syscall. If in doubt, write your own "touch" tool that only calls open and close once to test that you're getting the correct events. The source for Apple's touch command is available too if you need it.

Answer 2

If you look at what happens in the VNode scope, which gives more detail, you'll see that quite a lot occurs when you use touch. This is the output from a program based on the VNode monitor of Singh's "Mac OSX Internals", when I create a file called 'testtouch': -

09:00:51.262 Pid: 49 (fseventsd) "/Users/user/testtouch" VREG VT_HFS {READ_ATTRIBUTESREAD_SECURITY} 09:00:51.263 Pid: 49 (fseventsd) "/Users/user/testtouch" VREG VT_HFS {READ_ATTRIBUTESREAD_SECURITY} 09:00:51.278 Pid: 40 (mds) "/Users/user/testtouch" VREG VT_HFS {READ_ATTRIBUTES} 09:00:51.278 Pid: 40 (mds) "/Users/user/testtouch" VREG VT_HFS {WRITE_DATAACCESS} 09:00:51.278 Pid: 40 (mds) "/Users/user/testtouch" VREG VT_HFS {READ_DATAACCESS} 09:00:51.279 Pid: 40 (mds) "/Users/user/testtouch" VREG VT_HFS {EXECUTEACCESS} 09:00:51.279 Pid: 559 (mdworker) "/Users/user/testtouch" VREG VT_HFS {READ_DATA} 09:00:51.279 Pid: 559 (mdworker) "/Users/user/testtouch" VREG VT_HFS {READ_ATTRIBUTES} 09:00:51.280 Pid: 559 (mdworker) "/Users/user/testtouch" VREG VT_HFS {WRITE_DATAACCESS} 09:00:51.280 Pid: 559 (mdworker) "/Users/user/testtouch" VREG VT_HFS {READ_DATAACCESS} 09:00:51.280 Pid: 559 (mdworker) "/Users/user/testtouch" VREG VT_HFS {EXECUTEACCESS} 09:00:51.281 Pid: 559 (mdworker) "/Users/user/testtouch" VREG VT_HFS {READ_ATTRIBUTES} 09:00:51.286 Pid: 559 (mdworker) "/Users/user/testtouch" VREG VT_HFS {READ_EXTATTRIBUTES} 09:00:51.286 Pid: 559 (mdworker) "/Users/user/testtouch" VREG VT_HFS {READ_ATTRIBUTESREAD_SECURITY} 09:00:51.287 Pid: 559 (mdworker) "/Users/user/testtouch" VREG VT_HFS {READ_ATTRIBUTES} 09:00:51.287 Pid: 559 (mdworker) "/Users/user/testtouch" VREG VT_HFS {READ_ATTRIBUTES} 09:00:51.288 Pid: 559 (mdworker) "/Users/user/testtouch" VREG VT_HFS {WRITE_DATAACCESS} 09:00:51.288 Pid: 559 (mdworker) "/Users/user/testtouch" VREG VT_HFS {READ_DATAACCESS} 09:00:51.288 Pid: 559 (mdworker) "/Users/user/testtouch" VREG VT_HFS {EXECUTEACCESS} 09:00:51.289 Pid: 40 (mds) "/Users/user/testtouch" VREG VT_HFS {READ_ATTRIBUTES}

Interestingly, you can see that WRITE_DATAACCESS occurs 3 times. Note that this is two flags; WRITEDATA and ACCESS.

So from this data, it looks to me as the 3 opens correlate with what you're seeing, but you may have missed an open somewhere, or for some reason, it fails to notify you of one of them.

Answer 3

MacOS X contains many things which can open files too. Consider the indexing by Spotlight. Whenever you modify a file (i.e. open it and then close it), the Spotlight will eventually want to index it. This can explain why you see multiple open/close events.

You can verify this by analyzing with proc_selfpid() which will tell you PID of the process who caused the event. (This works because the KAuth callback is called directly from the thread belonging to the process, both for KAUTH_SCOPE_FILEOP and KAUTH_SCOPE_VNODE.)

Also I guess the difference between open and close event counts may be caused by process fork. Consider this case:

1. Process opens a file.
2. Process forks. I.e. child inherits file descriptor of the opened file.
3. Both parent and child processes will eventually close the descriptor (explicitly with close() or implicitly when process terminates)