I have a very odd failure. The app MusicBrainz Picard 1.3.2, when writing modified audio files to a Network Attached Storage (NAS_ file server, will sometimes spew hundreds of this message. While spewing, it hangs with a spinning beach ball until I Force Quit it.
What is causing this hang? How can I prevent it? When the hang occurs, what can I do to reset my computer or file server or connection so the hang stops happening?
I will upvote answers which can even shed light on what afpfs_FindForkRef refers to. For some reason, when I search for this term, I get zero hits on Google and DuckDuckGo search engines. I'm guessing "afpfs" stands for "Apple Filing Protocol File System".
Here is the message log around the time I Force Quit the hung app:
....
2016-09-03 23:38:15.000 kernel[0]: AFP_VFS afpfs_vnop_ioctl: afpfs_FindForkRef failed -1
2016-09-03 23:38:15.000 kernel[0]: AFP_VFS afpfs_vnop_ioctl: afpfs_FindForkRef failed -1
2016-09-03 23:38:15.000 kernel[0]: AFP_VFS afpfs_vnop_ioctl: afpfs_FindForkRef failed -1
2016-09-03 23:38:15.000 kernel[0]: *** kernel exceeded 500 log message per second limit - remaining messages this second discarded ***
2016-09-03 23:38:15.881 com.apple.xpc.launchd[1]: (org.musicbrainz.picard.79268[5403]) Service exited due to signal: Killed: 9
2016-09-03 23:38:20.927 SystemUIServer[1443]: Attempt to use XPC with a MachService that has HideUntilCheckIn set. This will result in unpredictable behavior: com.apple.backupd.status.xpc
2016-09-03 23:38:38.069 spindump[1708]: Saved hang report for MusicBrainz Picard version 1.3.2 (Picard 1.3.2) to /Library/Logs/DiagnosticReports/MusicBrainz Picard_2016-09-03-233838_MyMac.hang
Note the "kernel exceeded 500 log messages per second" message. When this app hangs, it seems like it is generating that log message as fast as its inner loop will let it.
This didn't occur earlier today, working on other data. It occurs now. It occurred a few days ago, with previous data. In the interim, something made it stop.
Other apps don't provoke this problem right now. If I have this app write to my local disk instead of to the NAS file server, the problem doesn't occur. If I disconnect and reconnect the file server, the problem occurs again. In the past, when I restarted both my Mac and the file server, the problem reoccured, but I haven't tried that this time.
My computer: MacBook Pro Retina, mid 2014, running OS X Yosemite 10.10.5
The app: MusicBrainz Picard 1.3.2, which adds metadata to audio files and moves the files to a target directory.
The source path: path of a music file on the file server, e.g. u'/Volumes/Qmultimedia/Music/_inbox/_tracks/Vancouver Academy of Music Symphony Orchestra/VAM Mozart Requiem 2014/02 Symphony No. 8 D. 759 "Unfinished"- I. Allegro moderato.flac' (175 chars)
The destination path: path of a modified music file on the file server, e.g. u'/Volumes/Qmultimedia/Music/master_tagged_files/Mozart, Wolfgang Amadeus, Schubert, Franz; Vancouver Academy of Music Symphony Orchestra, Dala, Leslie, Wood, Caitlin, Froese, Laurelle Jade, Rupolo, Rocco, Read, Zachary, Vancouver Bach Choir/Mozart Requiem _ Schubert _Unfinished_ Symphony/02 Symphony No. 8 in B minor, D. 759 _Unfinished__ I. Allegro moderato.flac' (363 characters)
The file server: a QNAP TS-219P, about 5 years old
The connection: via an entry in the left pane of a Finder window, "myServer(AFP)", with a server box image as its preview. WHen I do a right-click on this icon, and select "Get Info" from the pop-up menu, an Info window appears. In it, "General Info" reads, "Kind: Mac, Where: Network". "More Info" reads, (a spinning icon) with the message, "Fetching…".
The volume: The NAS server has several file system volumes. The volume in question is named "Qmultimedia", with a disk enclosure box and a cartoon of three humanoids as its preview. WHen I do a right-click on this icon, and select "Get Info" from the pop-up menu, an Info window appears. In it, "General" reads:
Server: afp://Gemini(AFP)._afpovertcp._tcp.local/Qmultimedia
Created: Sunday, 21. December, 2014 at 14:18
Modified: Today, 00:48
Format: AppleShare
Capacity: 2.95 TB
Available: 1.48 TB
Used: 1,474,284,388,352 bytes (1.47 TB on disk)
The hang report: there's a lot in the hang report, /Library/Logs/DiagnosticReports/MusicBrainz Picard_2016-09-03-233838_MyMac.hang, but here are some highlights:
Event: hang
Duration: 4.70s (process was unresponsive for 31 seconds before sampling)
Steps: 48 (100ms sampling interval)
Heaviest stack for the main thread of the target process:
48 start + 52 (MusicBrainz Picard + 3044) [0x100000be4]
48 main + 650 (MusicBrainz Picard + 4474) [0x10000117a]
48 py2app_main + 2683 (MusicBrainz Picard + 10075) [0x10000275b]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 943050) [0x1040353ca]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 942382) [0x10403512e]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 792742) [0x1040108a6]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 792454) [0x104010786]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 785344) [0x10400ebc0]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 792454) [0x104010786]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 789242) [0x10400fafa]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 792454) [0x104010786]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 785344) [0x10400ebc0]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 792454) [0x104010786]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 787402) [0x10400f3ca]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 784253) [0x10400e77d]
48 ??? (<F57E8887-372A-E630-588B-1148CCA29919> + 3464844) [0x107efbe8c]
48 ??? (<4172EABD-46BE-2722-C849-F7FB5632DED2> + 1324428) [0x10918158c]
48 ??? (<4172EABD-46BE-2722-C849-F7FB5632DED2> + 1314468) [0x10917eea4]
48 ??? (<4172EABD-46BE-2722-C849-F7FB5632DED2> + 1313524) [0x10917eaf4]
48 ??? (<CD803C71-F94D-524C-1A39-07D1A339A0F0> + 272000) [0x108485680]
48 -[NSApplication run] + 594 (AppKit + 551667) [0x7fff837caaf3]
48 -[NSApplication nextEventMatchingMask:untilDate:inMode:dequeue:] + 346 (AppKit + 593496) [0x7fff837d4e58]
48 _DPSNextEvent + 978 (AppKit + 596139) [0x7fff837d58ab]
48 _BlockUntilNextEventMatchingListInModeWithFilter + 71 (HIToolbox + 205099) [0x7fff8f07812b]
48 ReceiveNextEventCommon + 179 (HIToolbox + 205294) [0x7fff8f0781ee]
48 RunCurrentEventLoopInMode + 235 (HIToolbox + 206191) [0x7fff8f07856f]
48 CFRunLoopRunSpecific + 296 (CoreFoundation + 465880) [0x7fff887abbd8]
48 __CFRunLoopRun + 927 (CoreFoundation + 467391) [0x7fff887ac1bf]
48 __CFRunLoopDoSources0 + 269 (CoreFoundation + 469901) [0x7fff887acb8d]
48 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 17 (CoreFoundation + 526849) [0x7fff887baa01]
48 ??? (<4172EABD-46BE-2722-C849-F7FB5632DED2> + 1323008) [0x109181000]
48 ??? (<4172EABD-46BE-2722-C849-F7FB5632DED2> + 1317852) [0x10917fbdc]
48 ??? (<F57E8887-372A-E630-588B-1148CCA29919> + 3461518) [0x107efb18e]
48 ??? (<CD803C71-F94D-524C-1A39-07D1A339A0F0> + 588900) [0x1084d2c64]
48 ??? (<CD803C71-F94D-524C-1A39-07D1A339A0F0> + 562669) [0x1084cc5ed]
48 ??? (<F57E8887-372A-E630-588B-1148CCA29919> + 3465277) [0x107efc03d]
48 ??? (<CFFC31D5-41BF-BC16-2650-C745627427E7> + 26259) [0x104715693]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 933631) [0x104032eff]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 759914) [0x10400886a]
48 ??? (<96E177D6-BA68-399D-7325-FAA0DD7247EB> + 1026148) [0x104049864]
48 __psynch_cvwait + 10 (libsystem_kernel.dylib + 90422) [0x7fff8275b136]
*48 psynch_cvcontinue + 0 (pthread + 26910) [0xffffff7f80f9991e]
....
Thread 0x13ac3a 48 samples (1-48) priority 31 cpu time 4.697s
<thread QoS legacy, boosted, received importance donation from WindowServer [189], IO policy important>
48 thread_start + 13 (libsystem_pthread.dylib + 5101) [0x7fff8dd113ed] 1-48
48 _pthread_start + 176 (libsystem_pthread.dylib + 16343) [0x7fff8dd13fd7] 1-48
48 _pthread_body + 131 (libsystem_pthread.dylib + 16474) [0x7fff8dd1405a] 1-48
48 ??? (<4172EABD-46BE-2722-C849-F7FB5632DED2> + 161492) [0x1090656d4] 1-48
....
48 __fcntl + 10 (libsystem_kernel.dylib + 88482) [0x7fff8275a9a2] 1-48
*34 hndl_unix_scall64 + 22 (kernel + 2311718) [0xffffff8000434626] 1-34
....
*1 hndl_unix_scall64 + 10 (kernel + 2311706) [0xffffff800043461a] (running) 35
*13 hndl_unix_scall64 + 22 (kernel + 2311718) [0xffffff8000434626] 36-48
....
Entries nested below hndl_unix_scall64 seem to have to do with log messages, so I'm guessing that's where the messages come from. I'm guessing that symbol hndl_unix_scall64 is near where the calls go wrong.
Updated 2016-09-04: added examples of original and destination paths. Also, add this diagnosis finding. When I use Picard's internal scripting to truncate the length of its path segments to 160 characters, then the file saving succeeds. The afpfs_FindForkRef failed -1 are still poured into the console log by the hundreds, but only for a couple of seconds. Then they stop, and Picard does not hang. So, the overall length of the path, or the length of segments of the path, may be relevant.
Best Answer
From experimenting, here's a workaround.
Use Picard's scripting to limit the length of each segment of the path to which you rename the music files. This prevents the hang from lasting long, which answers one of the questions.
In Picard's File Naming options, use the script function
$truncate(field,length)to limit the size of each path segment. Thus, instead of:$if2(%albumartistsort%,%artist%)/%album/ $if($gt(%totaldiscs%,1),%discnumber%)$num(%tracknumber%,2) %title%use this (and the limit 160 is arbitrary; 300 and 100 also seem to work):
$truncate($if2(%albumartistsort%,%artist%),160)/$truncate(%album%,160)/ $truncate($if($gt(%totaldiscs%,1),%discnumber%)$num(%tracknumber%,2) %title%,160)There is no evidence that the hang is a state problem. It seems to be provoked reproducibly by the behaviour of the application. So, apart from changing the script you have Picard run, there is no need to reset the computer or server. That answers another of the questions.
This still does not answer what causes this hang, and how to prevent it at the root cause.