Uploaded image for project: 'Picard'
  1. Picard
  2. PICARD-844

Picard hangs, spewing "AFP_VFS afpfs_vnop_ioctl: afpfs_FindForkRef failed" on console

    Details

    • Type: Bug
    • Status: Open
    • Priority: Normal
    • Resolution: Unresolved
    • Affects Version/s: 1.3.2
    • Fix Version/s: None
    • Component/s: File Move & Rename
    • Labels:
      None
    • Environment:
      Mac OS X 10.10.5. Network attached storage (NAS) file server QNAP TS-219P.

      Description

      The app MusicBrainz Picard 1.3.2, on Mac OS X 10.10.5, 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.

      To reproduce:

      1. Select a Release with a Release Artist string of 200-300 characters. I reproduced the problem with: http://musicbrainz.org/release/b3d7a27b-1cb7-4c45-83cf-b4447bbcb357
      (Release by "Johann Sebastian Bach; Christoph Prégardien, Matthias Goerne, Christine Schäfer, Dorothea Röschmann, Bernarda Fink, Elisabeth von Magnus, Michael Schade, Markus Schäfer, Dietrich Henschel, Oliver Widmer, Arnold Schönberg Chor, Wiener Sängerknaben, Concentus Musicus Wien, Nikolaus Harnoncourt", 292 characters), and
      http://musicbrainz.org/release/2ef3a932-ada4-4ec9-85b3-331c8bfc0516
      (Release by "Wolfgang Amadeus Mozart, Franz Schubert; Vancouver Academy of Music Symphony Orchestra, Leslie Dala, Caitlin Wood, Laurelle Jade Froese, Rocco Rupolo, Zachary Read, Vancouver Bach Choir", 185 characters)

      2. In Picard 1.3.2, open an audio file to tag and rename. I used a FLAC file which was a track from the corresponding Release, but I guess you could use any audio file and lie to Picard about the Release.

      3. With Musicbrainz.org, select the Release with a long Release Artist string, from step 1, and make Picard open this Release in the tagger.

      4. Drag the audio file to a track in the Release.

      5. Press Save

      Expected behaviour:

      The file saves with no fuss. Picard updates the metadata and renames the file according to the tagger script.

      Observed behaviour:

      Picard hangs. In Activity Log of Mac OS, Picard shows as not responding.
      User must Force Quit in order to end the hang.

      The audio file is not renamed.

      Messages of the following kind pour onto the console's 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.

      Discussion:

      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" messages 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.

      I asked a Stack Exchange site for help understanding the Mac OS error messages. See http://apple.stackexchange.com/questions/251503/why-does-kernel0-afp-vfs-afpfs-vnop-ioctl-afpfs-findforkref-failed-1-pour , in case someone has diagnosed it.

        Attachments

          Activity

            People

            • Assignee:
              Unassigned
              Reporter:
              jim delahunt Jim DeLaHunt
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated: