Creation of sparse bundle images on NAS failing under 10.5.2

[mattclark04]

I'm unable to create SparseBundle images on the NV+ (running 4.00c1-p2, mounted over AFP). Time Machine has also stopped working on the NV+ since upgrading to 10.5.2, so I wonder if this is connected?

The output of 'hdiutil create -debug -size 50m -type SPARSEBUNDLE -layout GPTSPUD -fs HFS+ -volname test_sb /Volumes/backups-1/test.sparsebundle' is all fine up to the point where we get 'system+disk sync failed 45 (Operation not supported) [ignoring error and trying fsync()]'.

Any ideas what operation is not being supported, and how to work around it? I'd really like to get TM working again!

...
CBundleBackingStore::flush: entry with flags 00000001
CBundleBackingStore::flushBand(0.000000d=0,sector=524b94) process buffers ONLY
CBundleBackingStore::flushBands: flushBand(fd=6,sector=6) returned 0
CBundleBackingStore::flushBand(fd=6, sector=6) system + disk buffers
CBundleBackingStore::flushBand(fd=6,sector=6) system+disk sync failed 45 (Operation not supported) [ignoring error and trying fsync()]
CBundleBackingStore::flushBand(0.000000d=0,sector=93e3e30f0000002d) process buffers ONLY
CBundleBackingStore::flushBands: flushBand(fd=0,sector=0) returned 45
CBundleBackingStore::flushBands returned 45
CBundleBackingStore::flush: returning 45
2008-02-18 21:39:07.844 diskimages-helper[2961:3813] -serveImage: ALL DONE SERVING THE IMAGE (0)
2008-02-18 21:39:07.845 diskimages-helper[2961:1603] -ejectAfterFormat: synchronous eject returned 0x00000000 (0)
2008-02-18 21:39:07.846 diskimages-helper[2961:1603] -ejectAfterFormat: returning 0
2008-02-18 21:39:07.846 diskimages-helper[2961:3813] -decrementBackgroundThreadCount: entry with error 0.
2008-02-18 21:39:07.847 diskimages-helper[2961:1603] -prepareDiskImageForExport: at entry: baseBS length is 52428800.
2008-02-18 21:39:07.847 diskimages-helper[2961:3813] -decrementBackgroundThreadCount: _backgroundThreadCount is now 2.
2008-02-18 21:39:07.856 diskimages-helper[2961:1603] -prepareDiskImageForExport: finalizing returned 0 (Unknown error: 0).
CBundleBackingStore::flush: entry with flags 00000001
CBundleBackingStore::flushBand(0.000000d=0,sector=524b94) process buffers ONLY
CBundleBackingStore::flushBands: flushBand(fd=6,sector=6) returned 0
CBundleBackingStore::flushBand(fd=6, sector=6) system + disk buffers
CBundleBackingStore::flushBand(fd=6,sector=6) system+disk sync failed 45 (Operation not supported) [ignoring error and trying fsync()]
CBundleBackingStore::flushBand(0.000000d=0,sector=93e3e30f0000002d) process buffers ONLY
CBundleBackingStore::flushBands: flushBand(fd=0,sector=0) returned 45
CBundleBackingStore::flushBands returned 45
CBundleBackingStore::flush: returning 45
2008-02-18 21:39:07.867 diskimages-helper[2961:1603] -prepareDiskImageForExport: flushing returned 45 (Operation not supported).
2008-02-18 21:39:07.868 diskimages-helper[2961:1603] -prepareDiskImageForExport: at EXIT : baseBS length is 52428800.
status proc called: cleanup
2008-02-18 21:39:07.869 diskimages-helper[2961:1603] -performCleanupWithError:45
CBundleBackingStore::flushBand(0.000000d=0,sector=524b94) process buffers ONLY
CBundleBackingStore::flushBands: flushBand(fd=6,sector=6) returned 0
CBundleBackingStore::flushBand(fd=6, sector=6) system + disk buffers
CBundleBackingStore::flushBand(fd=6,sector=6) system+disk sync failed 45 (Operation not supported) [ignoring error and trying fsync()]
CBundleBackingStore::flushBand(0.000000d=0,sector=93e3e30f0000002d) process buffers ONLY
CBundleBackingStore::flushBands: flushBand(fd=0,sector=0) returned 45
CBundleBackingStore::releaseBand: closing fd=6, sector=6
CBundleBackingStore::releaseBands: releaseBand(fd=-1,sector=0) returned 0
CBundleBackingStore::closeDataFork: releaseBands returned 45
CBundleBackingStore::closeDataFork: returning 45
2008-02-18 21:39:07.875 diskimages-helper[2961:1603] deleting /Volumes/backups-1/test.sparsebundle
2008-02-18 21:39:07.895 diskimages-helper[2961:3d2f] -_handleMonitorThread exit
2008-02-18 21:39:07.896 diskimages-helper[2961:3d2f] -decrementBackgroundThreadCount: _backgroundThreadCount is now 1.
2008-02-18 21:39:08.028 diskimages-helper[2961:1603] DIHelperNBI performOperation: returning 45
2008-02-18 21:39:08.030 diskimages-helper[2961:1603] -[DIHelperHDID dealloc:]
2008-02-18 21:39:08.030 diskimages-helper[2961:10b] DIHelper _report_results: reporting {
payload = {
};
"result-code" = 45;
}
2008-02-18 21:39:08.031 diskimages-helper[2961:1603] -decrementBackgroundThreadCount: _backgroundThreadCount is now 0.
2008-02-18 21:39:08.032 hdiutil[2959:2203] reportResultsToFramework: proxy has finished operation
2008-02-18 21:39:08.033 hdiutil[2959:2203] reportResultsToFramework: results are: {
payload = {
};
"result-code" = 45;
}
2008-02-18 21:39:08.033 hdiutil[2959:2203] reportResultsToFramework: _threadResultsError is 45
2008-02-18 21:39:08.034 hdiutil[2959:2203] reportResultsToFramework: disconnecting from helper.
2008-02-18 21:39:08.134 hdiutil[2959:2203] disconnectFromHelper: removing observers
2008-02-18 21:39:08.135 hdiutil[2959:2203] disconnectFromHelper: terminating proxy
2008-02-18 21:39:08.137 diskimages-helper[2961:10b] DIHelper: terminateHelper: entry.
2008-02-18 21:39:08.138 hdiutil[2959:2203] disconnectFromHelper: terminated proxy
2008-02-18 21:39:08.238 diskimages-helper[2961:10b] -DIHelperAgentMaster terminateUIAgentConnection.
DIHLDiskImageCreate() returned 45
2008-02-18 21:39:08.241 diskimages-helper[2961:10b] DIHelper dealloc.
2008-02-18 21:39:08.242 diskimages-helper[2961:10b] -DIHelperAgentMaster terminateUIAgentConnection.
hdiutil: create failed - Operation not supported
Pearl:backups-1 matt$

[btaroli]

You're not alone... see my post in the Time Machine thread for a workaround.

[mattclark04]

Ah, I hadn't seen that post before - very helpful!

Do we know if anyone from Infrant/Netgear is looking into this or has an opinion?

[btaroli]

You're presuming it's a ReadyNAS issue... and it's not. Please note that the workaround(s) given the associated thread are workarounds for Apple issues. All we had to do on 10.5.0 and 10.5.1 was set a system option and go (creation of sparsebundle over network worked great). Now, suddenly in 10.5.2 we no longer need the system option but instead sparsebundle creation over network fails. Netgear changed nothing... this is an issue born of Apple's new code. And if you do any searching online (Internet, not just this site) you will absolutely find that there are others having this exact same issue, even those mounting their shares over AFP to another Mac OS X system...

[mattclark04]

I didn't mean to imply it was an issue with the ReadyNAS per se, but there's a good chance (absent any further information) that the fix might require an update to the NAS's AFP implementation. Then again maybe not, but I'm looking to Infrant for guidance on that!

[pjc]

Looking at the error messages hdiutil provides, it looks like this may be an Apple bug. It detects the failure of fullfsync, and then claims it's going to try to flush manually, but then it uses the wrong file descriptor:

Code: Select all

CBundleBackingStore::flushBand(fd=6,sector=6) system+disk sync failed 45 (Operation not supported) [ignoring error and trying fsync()]
CBundleBackingStore::flushBand(0.000000d=0,sector=93e3e30f0000002d) process buffers ONLY
CBundleBackingStore::flushBands: flushBand(fd=0,sector=0) returned 45

The first time it's using fd=6, the second time (retry), it uses fd=0. On my machine, the second attempt used a large negative integer. It looks like an uninitialized variable bug, one that wouldn't manifest itself on Apple servers, hence it sneaked by. (I've filed a bug report with Apple.)

Updated: It turns out this munged file descriptor isn't the problem (though it is another bug). It simply that the result of fsync() is being ignored. They are actually doing the fsync(), and it is actually successful.