"No target vnode found in rename action," spraying in dmesg

[incumbent]

hello,

I built a new pool (mirror 2x4TB) for my photo/audio workstation, and I'm currently rsync'ing my MailMate email stash to a dataset created with com.apple.browse=off (/pond/people/zemory/maildir/) and dmesg is flooded with messages like this:

Code: Select all

[ 5040.243372]: _FileopScopeListener_HandlePostOpRename:225 (1): No target vnode found in rename action, path=/pond/people/zemory/maildir/Messages.noindex/IMAP/emory@mailbox.eyrie.kvet.ch./Vault.mailbox/2018.mailbox/Messages/275522.eml, status=-2
[ 5040.244560]: _FileopScopeListener_HandlePostOpRename:225 (1): No target vnode found in rename action, path=/pond/people/zemory/maildir/Messages.noindex/IMAP/emory@mailbox.eyrie.kvet.ch./Vault.mailbox/2018.mailbox/Messages/275525.eml, status=-2
[ 5040.245614]: _FileopScopeListener_HandlePostOpRename:225 (1): No target vnode found in rename action, path=/pond/people/zemory/maildir/Messages.noindex/IMAP/emory@mailbox.eyrie.kvet.ch./Vault.mailbox/2018.mailbox/Messages/275528.eml, status=-2
[ 5040.246735]: _FileopScopeListener_HandlePostOpRename:225 (1): No target vnode found in rename action, path=/pond/people/zemory/maildir/Messages.noindex/IMAP/emory@mailbox.eyrie.kvet.ch./Vault.mailbox/2018.mailbox/Messages/275531.eml, status=-2
[ 5040.247863]: _FileopScopeListener_HandlePostOpRename:225 (1): No target vnode found in rename action, path=/pond/people/zemory/maildir/Messages.noindex/IMAP/emory@mailbox.eyrie.kvet.ch./Vault.mailbox/2018.mailbox/Messages/275534.eml, status=-2
[ 5040.248934]: _FileopScopeListener_HandlePostOpRename:225 (1): No target vnode found in rename action, path=/pond/people/zemory/maildir/Messages.noindex/IMAP/emory@mailbox.eyrie.kvet.ch./Vault.mailbox/2018.mailbox/Messages/275537.eml, status=-2
[ 5040.250191]: _FileopScopeListener_HandlePostOpRename:225 (1): No target vnode found in rename action, path=/pond/people/zemory/maildir/Messages.noindex/IMAP/emory@mailbox.eyrie.kvet.ch./Vault.mailbox/2018.mailbox/Messages/275540.eml, status=-2
[ 5040.251381]: _FileopScopeListener_HandlePostOpRename:225 (1): No target vnode found in rename action, path=/pond/people/zemory/maildir/Messages.noindex/IMAP/emory@mailbox.eyrie.kvet.ch./Vault.mailbox/2018.mailbox/Messages/275543.eml, status=-2
[ 5040.252592]: _FileopScopeListener_HandlePostOpRename:225 (1): No target vnode found in rename action, path=/pond/people/zemory/maildir/Messages.noindex/IMAP/emory@mailbox.eyrie.kvet.ch./Vault.mailbox/2018.mailbox/Messages/275546.eml, status=-2


When I pick one of the files mentioned and take a look at it, everything seems to be copacetic. I'm not filled with confidence by this "no target vnode" messages though. The rsync job running right now is using my user account, which has permissions to view and travel the whole way through `/pond/` and I use /etc/synthetic.conf to do my volume mappings (e.g. create /pond so i can `set mountpoint` to that; also shortcuts to other datasets like `/zemory/` which is a link to the full path of the dataset `/pond/people/zemory/`).

I'm using a dual-bay eSATA enclosure (connected via one of the eSATA ports on the back of my CalDigit Thunderbolt 2 dock) for this pool and it's been working well so far.

OR HAS IT?!

[lundman]

_FileopScopeListener_HandlePostOpRename. "No target vnode found in rename action,"

Seems to be some software listening to FILESYSTEM_EVENTS and it doesn't like that our events for rename isn't sending target. However
the events are generally sent by XNU, and not by us.

https://github.com/apple/darwin-xnu/blo ... fs.c#L4324

HFS does not issue any special events for rename either, so it doesn't look like we missed something. The message
seems to come from ClamAV.

[incumbent]

Code: Select all

_FileopScopeListener_HandlePostOpRename.  "No target vnode found in rename action,"

Seems to be some software listening to

Code: Select all

FILESYSTEM_EVENTS

and it doesn't like that our events for rename isn't sending target. However
the events are generally sent by XNU, and not by us.

Code: Select all

https://github.com/apple/darwin-xnu/blob/8f02f2a044b9bb1ad951987ef5bab20ec9486310/bsd/vfs/kpi_vfs.c#L4324

HFS does not issue any special events for rename either, so it doesn't look like we missed something. The message
seems to come from ClamAV.

jeeze I learn something every time I read a post of yours. i do have clamav installed on this workstation but i only use it for adhoc scanning.

however! i *do* have Bitdefender as my endpoint protection software. i run it pretty hobbled on purpose [1] but i suppose it could still be looking even if it isn't configured to intervene or something?

i know you're busy but if you have a quick answer to "why did you think it was AV/anti-malware software based on `kpc_vfs.c` or the messages on console" it would help me investigate better next time!


[1] i'm an IT Security architect so i regularly handle code repositories, tools, exploit code, and more importantly books and research databases and papers and conference decks etc etc that require good hygiene. and ever since SEP ruined like 200 books in my Books library a few years ago i tend to avoid any feature that alters/"cleans" files. i have it set to protect time machine from ransomware (non-zfs APFS volume) but disabled the real-time access protection feature so I'm curious if even when it's disabled it still watches passively or if you were literally saying it is specifically ClamAV that is doing that because I don't believe I have clamav configured to do anything automatically, at least not on purpose.

[lundman]

Nothing too fancy, I only spent a couple of minutes on it to get a feel for the issue. And it looked like
libclamav has a function with that name, which doesn't have to be the actual product ClamAV, but
probably something Apple uses internally. Let's dig deeper.

Searching the XNU sources for "FileopScopeListener" shows no hits, but
https://github.com/search?q=FileopScope ... ension%3Ac

Shows up things (eventually) in clamav, google finds us a spindump with

Code: Select all

                              12  _CFPrefsWritePlistToFDThenClose + 807 (CoreFoundation + 1553804) [0x7fff2ffa958c]
                                12  __rename + 10 (libsystem_kernel.dylib + 15402) [0x7fff6a060c2a]
                                 *12  hndl_unix_scall64 + 22 (kernel + 791046) [0xffffff80002c1206]
                                   *6   unix_syscall64 + 909 (kernel + 7884093) [0xffffff8000984d3d]
                                     *6   throttle_lowpri_io + 974 (kernel + 3915886) [0xffffff80005bc06e]
                                       *6   thread_block_reason + 175 (kernel + 1289487) [0xffffff800033ad0f]
                                         *6   ??? (kernel + 1295569) [0xffffff800033c4d1]
                                           *6   machine_switch_context + 200 (kernel + 2365544) [0xffffff8000441868]
                                   *6   unix_syscall64 + 647 (kernel + 7883831) [0xffffff8000984c37]
                                     *6   ??? (kernel + 3747965) [0xffffff800059307d]
                                       *6   kauth_authorize_fileop + 384 (kernel + 6520672) [0xffffff8000837f60]
                                         *6   FileopScopeListener + 738 (AppleFileUtil + 28078) [0xffffff7f816a7dae]
                                           *6   _FileopScopeListener_HandlePostOpRename + 109 (AppleFileUtil + 29240) [0xffffff7f816a8238]
                                             *6   vnode_lookup + 154 (kernel + 3649434) [0xffffff800057af9a]
                                               *6   namei + 3521 (kernel + 3595873) [0xffffff800056de61]



It looks like then that "AppleFileUtil" has the function in this case, (run by "cfprefsd" in this case). Ie
/System/Library/Extensions/AppleFileUtil.kext

Looking inside:
# strings /System/Library/Extensions/AppleFileUtil.kext/Contents/MacOS/AppleFileUtil |less

it seems to be built from: com.apple.xbs/Sources/FileUtil/FileUtil-8/Kernel/Sync/daemons.c

Unfortunately, it seems that Apple has not released sources for it, but we can at least find:

"No target vnode found in rename action, path=%s, status=%d"

Looking at hfs sources for rename
https://github.com/Darm64/hfs/blob/e978 ... ps.c#L4487

there isn't anything in there for events, but they do go and call vnode_update_identity() both for name and parent.
Possibly we should too, but it'd be nice to know why the error triggers. Anyone have IDA pro installed?