zfs
zfs copied to clipboard
Published
20 hours ago •
openzfsonosx
openzfsonosx
Photos cannot import photos to library on zfs
While similar, I believe this issue is different than #747 because no error message is given in this case, that issue was closed, and I have followed the suggested property settings.
I loaded my Photos library, which had been on a Big Sur Intel-based system, on a new M1 Pro macbook which shipped with Monterey installed. I am not able to import new photos into the Photos app when the library is on a zfs filesystem.
I tried creating a new Photos library both on and off of the ZFS fs -- the non-ZFS library works, the ZFS-hosted library will not import a photo
To reproduce
- Create a new Photos library on a ZFS filesystem
- attempt to import a single photo
It never imports it but never fails with an error message either. However, if I try to import the photo a second time, Photos complains that "Another import session is in progress. Please try again when the current task is complete." It will try again if I quit Photos and restart it. But, it is still the same result. It will not import anything.
I tried off, hfs, and apfs for com.apple.mimic. Normally, I have used hfs on older machines.
Following is some information about my installation
emilybaldwin@Emily ~ % id
uid=501(emilybaldwin) gid=20(staff) groups=20(staff),12(everyone),61(localaccounts),79(_appserverusr),80(admin),81(_appserveradm),98(_lpadmin),701(com.apple.sharepoint.group.1),33(_appstore),100(_lpoperator),204(_developer),250(_analyticsusers),395(com.apple.access_ftp),398(com.apple.access_screensharing),399(com.apple.access_ssh),400(com.apple.access_remote_ae)
emilybaldwin@Emily ~ % uname -a
Darwin Emily.ecbaldwin.net 21.1.0 Darwin Kernel Version 21.1.0: Wed Oct 13 17:33:01 PDT 2021; root:xnu-8019.41.5~1/RELEASE_ARM64_T6000 arm64
emilybaldwin@Emily ~ % zfs version
zfs-macOS-2.1.0-1
zfs-kmod-2.1.0-1
emilybaldwin@Emily ~ % zpool list
NAME SIZE ALLOC FREE CKPOINT EXPANDSZ FRAG CAP DEDUP HEALTH ALTROOT
emilyzpool 1.36T 557G 835G - - 2% 39% 1.00x ONLINE -
emilybaldwin@Emily ~ % zfs list
NAME USED AVAIL REFER MOUNTPOINT
emilyzpool 557G 792G 2.92M /Volumes/emilyzpool
emilyzpool/photos 557G 792G 496G /Volumes/emilyzpool/photos
emilybaldwin@Emily ~ % ls -l /Volumes/emilyzpool/photos
total 119
drwxr-xr-x@ 9 emilybaldwin staff 18 Mar 17 2020 Carl
drwxr-xr-x@ 8 emilybaldwin staff 11 Nov 8 08:44 Lydias iPhoto.photoslibrary
drwxr-xr-x@ 6 emilybaldwin staff 7 Mar 16 2020 Misc
drwxr-xr-x@ 8 emilybaldwin wheel 8 Dec 2 20:21 Photos Library 2.photoslibrary
drwxr-xr-x@ 8 emilybaldwin wheel 8 Dec 4 15:36 Photos Library 2021-11.photoslibrary
drwxr-xr-x@ 5 emilybaldwin staff 6 Mar 17 2020 Wedding Photos
drwxr-xr-x@ 11 emilybaldwin staff 27 Dec 4 15:34 iPhoto Library.photoslibrary
emilybaldwin@Emily ~ % sudo zfs get all emilyzpool/photos | awk '$NF != "default" {print}'
NAME PROPERTY VALUE SOURCE
emilyzpool/photos type filesystem -
emilyzpool/photos creation Sat Nov 6 17:05 2021 -
emilyzpool/photos used 557G -
emilyzpool/photos available 792G -
emilyzpool/photos referenced 496G -
emilyzpool/photos compressratio 1.00x -
emilyzpool/photos mounted yes -
emilyzpool/photos devices off local
emilyzpool/photos createtxg 906 -
emilyzpool/photos canmount on received
emilyzpool/photos version 5 -
emilyzpool/photos utf8only off -
emilyzpool/photos normalization none -
emilyzpool/photos casesensitivity sensitive -
emilyzpool/photos guid 12403212368317359934 -
emilyzpool/photos usedbysnapshots 60.6G -
emilyzpool/photos usedbydataset 496G -
emilyzpool/photos usedbychildren 0B -
emilyzpool/photos usedbyrefreservation 0B -
emilyzpool/photos objsetid 101 -
emilyzpool/photos refcompressratio 1.00x -
emilyzpool/photos written 2.05G -
emilyzpool/photos logicalused 548G -
emilyzpool/photos logicalreferenced 489G -
emilyzpool/photos com.apple.mimic hfs local
emilyzpool/photos com.apple.devdisk on local
Here are the console logs around a recent attempt to import. I see the Photos process and deleted process reporting errors. A few things that catch my eye are:
unable to validate volume "/Volumes/emilyzpool/photos"Encountered error requesting purge of 9.3 MB. Error string: "<private>"ERROR: <private> (type: not-enough-storage-space, path: (null)), file: <private>, line: 392
See the full text for more detail.
default 19:23:00.001861-0700 bluetoothd PowerManager power state is 1
default 19:23:00.003572-0700 bluetoothd PowerManager power state is 1
default 19:23:00.005845-0700 bluetoothd Posting Bluetooth Status Notification <private>
default 19:23:00.024738-0700 powerd stored ts 1639504025, current ts 1639534980
default 19:23:00.025525-0700 powerd Battery time remaining posted(0x200000000480370) Time:880 Source:Batt
default 19:23:00.030662-0700 powerd kIOPSNotifyTimeRemaining state 144115188080575344
default 19:23:00.031383-0700 powerd kIOPSNotifyTimeRemaining state 144115188080575344
default 19:23:00.103857-0700 cloudd tcp_input [C153.1:3] flags=[F.] seq=917832440, ack=2078086776, win=501 state=ESTABLISHED rcv_nxt=917832440, snd_una=2078086776
default 19:23:00.104062-0700 cloudd nw_protocol_tcp_log_summary [C153.1:3]
[BE2F58AA-728C-4E2A-B54D-B73916CF9AC0 <private>:62241<-><private>:443]
Init: 1, Conn_Time: 9.459ms, SYNs: 1, WR_T: 0/0, RD_T: 0/0, TFO: 0/0/0, ECN: 0/0/0, TS: 1
rtt_cache: none, rtt_upd: 10, rtt: 10.312ms, rtt_var: 2.562ms rtt_nc: 10.312ms, rtt_var_nc: 2.562ms base rtt: 9ms
ACKs-compressed: 0, ACKs delayed: 0 delayed ACKs sent: 0
default 19:23:00.104151-0700 cloudd tcp_input [C153.1:3] flags=[F.] seq=917832440, ack=2078086776, win=501 state=CLOSE_WAIT rcv_nxt=917832441, snd_una=2078086776
default 19:23:00.106161-0700 cloudd Connection 153: read-side closed
default 19:23:00.106226-0700 cloudd Connection 153: read-side closed
default 19:23:00.106266-0700 cloudd Connection 153: read-side closed
default 19:23:00.106770-0700 cloudd Connection 153: cleaning up
default 19:23:00.106897-0700 cloudd [C153 A9F144D5-CF9D-4897-A0A1-794041A7AF0C Hostname#8b2cd95d:443 tcp, bundle id: com.apple.bird, url hash: 951628b3, tls, definite, attribution: developer] cancel
default 19:23:00.107129-0700 cloudd [C153 A9F144D5-CF9D-4897-A0A1-794041A7AF0C Hostname#8b2cd95d:443 tcp, bundle id: com.apple.bird, url hash: 951628b3, tls, definite, attribution: developer] cancelled
[C153.1 5C2ABFFC-F222-40A4-BA08-CAB5C82FFB24 10.224.24.186:62241<->IPv4#86c39328:443]
Connected Path: satisfied (Path is satisfied), viable, interface: en0, ipv4, dns
Privacy Stance: Not Eligible
Duration: 30.327s, DNS @0.000s took 0.057s, TCP @0.063s took 0.010s, TLS 1.3 took 0.052s
bytes in/out: 8024/2839, packets in/out: 17/25, rtt: 0.010s, retransmitted bytes: 0, out-of-order bytes: 0
default 19:23:00.108197-0700 cloudd nw_flow_disconnected [C153.1 IPv4#86c39328:443 cancelled channel-flow ((null))] Output protocol disconnected
default 19:23:00.111052-0700 cloudd nw_connection_report_state_with_handler_on_nw_queue [C153] reporting state cancelled
default 19:23:00.112312-0700 cloudd tcp_output [C153.1:3] flags=[F.] seq=2078086839, ack=917832441, win=2048 state=LAST_ACK rcv_nxt=917832441, snd_una=2078086776
error 19:23:00.114835-0700 cloudd tcp_input [C153.1:3] flags=[R.] seq=917832441, ack=2078086839, win=501 state=LAST_ACK rcv_nxt=917832441, snd_una=2078086839
error 19:23:00.117881-0700 cloudd tcp_input [C153.1:3] flags=[R] seq=917832441, ack=0, win=0 state=CLOSED rcv_nxt=917832441, snd_una=2078086839
default 19:23:00.260812-0700 kernel LQM-WIFI-CT: ofdmDesense=0 bphyDesense=0 reason=0x0
default 19:23:00.405906-0700 kernel LQM-WiFi: WeightAvgLQM rssi=-58 snr=22 txRate=253125 rxRate=315000
default 19:23:00.406008-0700 kernel postMessageInternal:isPipeOpened:0, msg 145, dataLen 16
default 19:23:00.642710-0700 com.apple.appkit.xpc.openAndSavePanelService "The connection to ACDAccountStore was invalidated."
default 19:23:00.695223-0700 bluetoothd [MacUserClient][NotificationEventHandler] -- Received Heart Beat notification -- HIDShim
error 19:23:00.714723-0700 WindowServer __CFRunLoopModeFindSourceForMachPort returned NULL for mode 'kCFRunLoopDefaultMode' livePort: 914963
default 19:23:00.755620-0700 runningboardd Assertion did invalidate due to timeout: 406-350-74907 (target:[app<application.com.apple.Photos.1152921500311928792.1152921500311932604(501)>:26433])
default 19:23:00.779232-0700 kernel LQM-WiFi-PHY: ChanSpec 149 a 40MHz l, slice=0 phyWdg=4244 noiseReq=2963 noiseCrsbit=0 noiseApply=40 calCnt=21 crsminPwrIdx=10 featureflag=0x0044 chanSwitchCnt=179 chipTemp=26 femTemp=-50 rxChain=3 txChain=3
default 19:23:00.779257-0700 kernel LQM-WiFi-PHY: ChanSpec 149 a 40MHz l, slice=0 ofdmDesense=0 bphyDesense=0 gbdBphySleepCnt=4 gbdOfdmSleepCnt=1 homeChan=0x97 deafCnt=0 btcxMode=0 ltecxMode=0 phyCalDisable=0 noiseMmtOverdue=0 crsminPwrApplyCnt=120
default 19:23:00.779268-0700 kernel LQM-WiFi-PHY: ChanSpec 149 a 40MHz l, slice=0 weakestRssi=-59 edThreshold=-77 edCrsStatus=0x0000 preemptStatus1=0x0e20 preemptStatus2=0x4ef7 preemptStatus3=0x0106 preemptStatus4=0x0000 glitch=54 bphyGlitch=0 badplcp=7 bphyBadplcp=0
default 19:23:00.779277-0700 kernel LQM-WiFi-PHY: ChanSpec 149 a 40MHz l, slice=0 ccaDurMS=1000 ccaEdDuration=0 crsminPwr0=-92 noiseLevelInst0=-93 crsminPwr1=-91 noiseLevelInst1=-93
default 19:23:00.779469-0700 kernel postMessageInternal:isPipeOpened:0, msg 174, dataLen 64
default 19:23:00.784085-0700 WindowServer [HID] [MT] dispatchEvent Dispatching event with 2 children, _eventMask=0x42 _childEventMask=0x42 Cancel=0 Touching=0 inRange=1
default 19:23:00.791511-0700 kernel LQM-WiFi: (5G) rxNotPrimary20s=319 ucodeLateDrop=0 rxInvalidUcodeLateWrongMACPHY=0 rxLate30us=0 rxLegacyFrmInvalid=0 txSifsErr=0 ooseqMacSusp=0
default 19:23:00.791594-0700 kernel LQM-WIFI: slow-wifi featureEnabled:1 Channel:149 chWidth:40 phyMode:128 nss:2 RSSI:-58 CCA:8 SNR:22 offChanDurUS:0 TVPMDurMS:0 concurrentIntDurMS:0 randomMac:0 dataStallScore:100 networkScore:100
default 19:23:00.791599-0700 kernel LQM-WIFI: slow-wifi btAntDurMS:0 btESCO:0/0 rc1CoexDurMS:0 rc2CoexDurMS:0 lteCoexDurMS:0 totalNonWLANDurMS:0 infraDutyCycle:100 lastScanType:0
default 19:23:00.791603-0700 kernel LQM-WIFI: slow-wifi availWLANDurMS:5039 availTxDurMS:4842 realTxDurMS:9 availRxDurMS:5030 realRxDurMS:197 measurementDurMS:5039 lastScanDurMS:0
default 19:23:00.791611-0700 kernel LQM-WIFI: slow-wifi Tx tput (i/p:0 o/p:0 expected:0)Mbps queueFullDurMS:0 avgLatencyMS:1 maxLatencyMS:4 phyRate(mode:270 avg:254 expected:411) phyRateTputRatio:0
default 19:23:00.791615-0700 kernel LQM-WIFI: slow-wifi Tx AMPDUDensity(actual:0 expectedAtQueueFull:64) retries:7 fails:0 fwFrames:97 hostFrames:150 hostFails:0 ctlPkts:1(502) symptomsFails:0
default 19:23:00.791620-0700 kernel LQM-WIFI: slow-wifi TxLim[1] outputBelowExpected:0 outputBelowInput:0 lowTxFrameCount:1 queueFull:0 highLatency:0 baselineNotAllowed:0 highSymptomsFails:0
default 19:23:00.791623-0700 kernel LQM-WIFI: slow-wifi TxLim[1] lowPhyRate:0 lowPhyRateTputRatio:0 highPER:0 highRetries:0 lowTxAMPDUDensity:0 lowCCA:1 activeCoex:0 hostFWMismatch:0
default 19:23:00.791629-0700 kernel LQM-WIFI: slow-wifi Rx tput:0 Mbps baseline:0 Mbps overflows:0 fcsFail:13 plcpBad:47 goodPlcps:1376 crsGlitches:382 fwFrames:1265 ucastFWFrames:114 hostFrames:97 AmpduDUP:0 APTxDataStallPct:0 rxAmpduTxBaMismatch:0
default 19:23:00.791631-0700 kernel LQM-WIFI: slow-wifi Rx ucast(replays:0 decryptErrs:0) mcast(replays:0 decryptErrs:0) phyRate(mode:270 avg:289 expected:411) dups:0 retries:0 phyRateTputRatio:0
default 19:23:00.791635-0700 kernel LQM-WIFI: slow-wifi RxLim[1] highRetries:0 highPhyPER:0 highDataPER:0 highOverflows:0 highRSSI:1 lowPhyRate:0 lowPhyRateTputRatio:0
default 19:23:00.791640-0700 kernel LQM-WIFI: slow-wifi RxLim[1] highFCSErrors:0 highDups:0 highReplays:0 highDecryptErrors:0 highMCDecryptErrors:0 lowRxFrameCount:1
default 19:23:00.791646-0700 kernel LQM-WIFI: UI Entry curState:Idle prevState:PendingIP event:ChannelQualityUpdate data:1
default 19:23:00.791650-0700 kernel LQM-WIFI: UI Exit curState:Idle prevState:PendingIP
default 19:23:00.791724-0700 kernel postMessageInternal:isPipeOpened:0, msg 175, dataLen 140
default 19:23:00.791743-0700 kernel postMessageInternal:isPipeOpened:0, msg 155, dataLen 12
default 19:23:00.825225-0700 kernel postMessageInternal:isPipeOpened:0, msg 155, dataLen 12
default 19:23:00.830801-0700 runningboardd Acquiring assertion targeting [app<application.com.apple.Photos.1152921500311928792.1152921500311932604(501)>:26433] from originator [daemon<com.apple.powerd>:321] with description <RBSAssertionDescriptor| "App is holding power assertion" ID:406-321-74909 target:26433 attributes:[
<RBSDomainAttribute| domain:"com.apple.appnap" name:"PowerAssertion" sourceEnvironment:"(null)">,
<RBSAcquisitionCompletionAttribute| policy:AfterApplication>
]>
default 19:23:00.830851-0700 runningboardd Assertion 406-321-74909 (target:[app<application.com.apple.Photos.1152921500311928792.1152921500311932604(501)>:26433]) will be created as active
default 19:23:00.831290-0700 runningboardd Calculated state for app<application.com.apple.Photos.1152921500311928792.1152921500311932604(501)>: running-active (role: UserInteractiveFocal)
default 19:23:00.831383-0700 runningboardd [app<application.com.apple.Photos.1152921500311928792.1152921500311932604(501)>:26433] Ignoring jetsam update because this process is not memory-managed
default 19:23:00.831543-0700 runningboardd [app<application.com.apple.Photos.1152921500311928792.1152921500311932604(501)>:26433] Ignoring suspend because this process is not lifecycle managed
default 19:23:00.831645-0700 runningboardd [app<application.com.apple.Photos.1152921500311928792.1152921500311932604(501)>:26433] Ignoring GPU update because this process is not GPU managed
default 19:23:00.830516-0700 powerd updateAppSleepStates: Setting app nap state to true for 26433 because of power assertion
default 19:23:00.833126-0700 Photos cacheKey: <private>, newResult: (null)
default 19:23:00.833872-0700 deleted totalAvailable ENTRY, Volume: /Volumes/emilyzpool/photos, Calling process: Photos
default 19:23:00.833920-0700 deleted totalAvailable info CACHE_DELETE_ID : com.apple.cache_delete
default 19:23:00.834388-0700 deleted totalAvailable info CACHE_DELETE_QUERY_PATH : FAST
default 19:23:00.834404-0700 deleted totalAvailable info CACHE_DELETE_VOLUME : /Volumes/emilyzpool/photos
default 19:23:00.834438-0700 deleted caller has NOT requested a forceRefresh (CACHE_DELETE_NO_CACHE = NO, or is not present)
error 19:23:00.835526-0700 deleted CFDictionaryGetValue (kDADiskDescriptionVolumeUUIDKey) failed
error 19:23:00.837801-0700 deleted CFDictionaryGetValue (kDADiskDescriptionVolumeUUIDKey) failed
error 19:23:00.837937-0700 Photos cacheResults not caching due to error: <private>
error 19:23:00.837832-0700 deleted unable to validate volume "/Volumes/emilyzpool/photos"
error 19:23:00.838835-0700 deleted CFDictionaryGetValue (kDADiskDescriptionVolumeUUIDKey) failed
default 19:23:00.839138-0700 Photos purged: (null) bytes from (null)
error 19:23:00.839082-0700 deleted CFDictionaryGetValue (kDADiskDescriptionVolumeUUIDKey) failed
error 19:23:00.839202-0700 Photos PLCacheDeleteClient: Encountered error requesting purge of 9.3 MB. Error string: "<private>"
error 19:23:00.840173-0700 Photos ERROR: <private> (type: not-enough-storage-space, path: (null)), file: <private>, line: 392
default 19:23:00.866295-0700 corebrightnessd levelPercentage 0.372505, level = 5.523679 (nits/pwm), lux = 20.000000
default 19:23:00.867358-0700 WindowServer applyPWM:5523 fadeSpeed:350
default 19:23:00.868398-0700 WindowServer Display 1 commitBrightness sdr: -1, headroom: -1, ambient: 6.5326, filtered ambient: 20.5228, limit: -1
error 19:23:00.872910-0700 corebrightnessd failed to update sensor sensitivity
default 19:23:00.875610-0700 WindowServer Display 1 setting filtered ambient lux to 20.5228
default 19:23:00.879684-0700 runningboardd Calculated state for app<application.com.apple.Photos.1152921500311928792.1152921500311932604(501)>: running-active (role: UserInteractiveFocal)
default 19:23:00.879704-0700 runningboardd [app<application.com.apple.Photos.1152921500311928792.1152921500311932604(501)>:26433] Ignoring jetsam update because this process is not memory-managed
default 19:23:00.879722-0700 runningboardd [app<application.com.apple.Photos.1152921500311928792.1152921500311932604(501)>:26433] Ignoring suspend because this process is not lifecycle managed
default 19:23:00.879735-0700 runningboardd [app<application.com.apple.Photos.1152921500311928792.1152921500311932604(501)>:26433] Ignoring GPU update because this process is not GPU managed
Could you try opening Console.app and after entering an admin username and password (so you can view all system messages) try filtering with a search for "sandbox", and then try importing into Photos again?
I'm curious if you'll get a bunch of sandbox related errors relating to your Photos library; if you do then what you're seeing may be the same issue I'm experiencing with Xcode.app and a few other programs, in which case giving Photos Full Disk Access (in System Preferences -> Security & Privacy -> Privacy) may resolve the issue for you. You shouldn't need to do it of course, but if it does solve the issue then this will at least confirm that the issue is probably the same.
This bug isn't specific to zfs. I can easily reproduce it on my vanilla Mac running 12.4 using apfs. I've given full disk access to iPhoto, but the problem persists. I've studied the console error messages; they lack useful information. I suspect that this is one of several bugs in iPhotos. iPhotos has several bugs related to importing, sharing, and deleting images.
I'm having a similar problem on with OpenZFS 2.1 and macOS 12.5 on my M1 Ultra; I did find a bunch of sandbox messages, and gave both Photos and photoanalysisd full disk access, but am still getting sandbox messages about Photos... and it's not clear that my iCloud Photo Library is actually updating.
For what it's worth, I'm now testing on macOS Monterey 12.6, and Photos imports into photoslibrary libraries on ZFS volumes now, but unfortunately, I discovered that exporting photos that have had edits applied in Photos fails with "Unknown Error" unless the photoslibrary is indeed on APFS or HFS+.
Accordingly, I plan to (and recommend that we) use a ZVOL as raw block storage for an APFS or HFS+ filesystem, and store our photoslibrary libraries there.
