Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Photos cannot import photos to library on zfs #794

Open
ecbaldwin opened this issue Dec 15, 2021 · 5 comments
Open

Photos cannot import photos to library on zfs #794

ecbaldwin opened this issue Dec 15, 2021 · 5 comments

Comments

@ecbaldwin
Copy link

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

  1. Create a new Photos library on a ZFS filesystem
  2. 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
@ecbaldwin
Copy link
Author

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:

  1. unable to validate volume "/Volumes/emilyzpool/photos"
  2. Encountered error requesting purge of 9.3 MB. Error string: "<private>"
  3. 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

@Haravikk
Copy link

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.

@jeffstearns
Copy link

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.

@dmzimmerman
Copy link

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.

@chuckaeronut
Copy link

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.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants