requestAVAssetForVideo returns AVAsset==nil while networkAccessAllowed=true

Media Technologies Photos & Camera
shobi OP
Created Mar ’18
Replies 3
Boosts 0
Views 2.7k
Participants 2

Hi,

We have a large number of users complaining about unable to use iCloud assets.

We were able to reproduce it once in-house with a specific asset (movie file , 21 sec, 60fps). this asset can be playback in our app and in Photos app,

but trying to download it into the device with PHImageManager:requestAVAssetForVideo (setting networkAccessAllowed==true) returns AVAsset==nil.

the info dictionary is :

{

PHImageResultDeliveredImageFormatKey = 0;

PHImageResultIsInCloudKey = 1;

PHImageResultWantedImageFormatKey = 20001;

}



The console looks like containing viable messages, but crypto to us, regarding cloudd.

Should I open a bug?


here are the log details:

default 12:51:52.272271 +0200 Mxxxxxx ***************** requestAVAssetForVideo START *****************

default 12:51:52.274638 +0200 Mxxxxxx -[iCloudDownloadQueue downloadNextItem] itemIdentifier:871E0D6B-2158-4AD4-8814-16C33D94B988/L0/001

default 12:51:52.275218 +0200 Mxxxxxx ANALYTICS WRAPPER (BK tracker): log category:"UPLOAD_MANAGER MANUAL" event:"ICLOUD DOWNLOAD REQUIRED" label:"video asset"

default 12:51:52.311707 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:0.0000 err:(null)

default 12:51:52.312093 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:0.0000 err:(null)

default 12:51:52.320335 +0200 cloudd [Operation 0x16121d6a0] Initialized with context 0x1613711b0. Background: 0, cellular: 1, QOS: 0x19

default 12:51:52.321506 +0200 cloudd [Operation 0x16121d6a0] Starting operation

default 12:51:52.328117 +0200 cloudd [Operation 0x16121d6a0] Operation transitioning from state 1 (cancelled=0, stop=0, error=0)

default 12:51:52.362853 +0200 cloudd [Operation 0x16121d6a0] Request 0x15fdf1c50 set on operation

default 12:51:52.367461 +0200 cloudd [Request 0x15fdf1c50] Performing

default 12:51:52.371042 +0200 cloudd [Request 0x15fdf1c50] Getting URL for the user partition

default 12:51:52.372302 +0200 cloudd [Request 0x15fdf1c50] Getting configuration

default 12:51:52.373937 +0200 cloudd [Operation 0x16121d6a0] Operation is now in state 2

default 12:51:52.375090 +0200 cloudd [Request 0x15fdf1c50] Fetching container scoped user ID

default 12:51:52.376734 +0200 cloudd [Request 0x15fdf1c50] Getting device ID

default 12:51:52.378053 +0200 cloudd [Request 0x15fdf1c50] Getting zone gates

default 12:51:52.410040 +0200 accountsd "SecItemCopyMatching result: -25300 - keychain item com.apple.appleaccount.cloudkit.token - username <private>"

default 12:51:52.415710 +0200 cloudd [Request 0x15fdf1c50] Getting push token

default 12:51:52.416443 +0200 cloudd Creating a new client context 0x15fe96df0

default 12:51:52.416795 +0200 cloudd [Request 0x15fdf1c50] Performing request. Background=0, cellular=1

default 12:51:52.467271 +0200 cloudd TIC TCP Conn Start [149:0x15ff72350]

default 12:51:52.775902 +0200 itunesstored TIC TCP Conn Cancel [310:0x10b1d29c0]

default 12:51:52.776946 +0200 itunesstored __nw_socket_service_writes_block_invoke sendmsg(fd 33, 31 bytes): socket has been closed

default 12:51:52.777926 +0200 itunesstored TIC TCP Conn Destroyed [310:0x10b1d29c0]

default 12:51:52.974226 +0200 CommCenter QMI: Svc=0xe2(BSP) Req MsgId=0xe002 Bin=[<private>]

default 12:51:53.033032 +0200 CommCenter QMI: Svc=0xe2(BSP) Resp MsgId=0xe002 Bin=[<private>]

default 12:51:53.043204 +0200 cloudd TIC TCP Conn Event [149:0x15ff72350]: 1 Err(0)

default 12:51:53.043426 +0200 cloudd TIC TCP Conn Connected [149:0x15ff72350]: Err(0)

default 12:51:53.044073 +0200 cloudd TIC Enabling TLS [149:0x15ff72350]

default 12:51:53.077903 +0200 Mxxxxxx TIC TCP Conn Cancel [11:0x174388c90]

default 12:51:53.080234 +0200 Mxxxxxx __nw_socket_service_writes_block_invoke sendmsg(fd 26, 31 bytes): socket has been closed

default 12:51:53.477593 +0200 cloudd TIC TLS Event [149:0x15ff72350]: 2, Pending(0)

default 12:51:53.486101 +0200 cloudd TIC TLS Event [149:0x15ff72350]: 11, Pending(0)

default 12:51:53.528421 +0200 cloudd TIC TLS Event [149:0x15ff72350]: 22, Pending(0)

default 12:51:53.555062 +0200 cloudd TIC TLS Event [149:0x15ff72350]: 12, Pending(0)

default 12:51:53.556589 +0200 cloudd TIC TLS Event [149:0x15ff72350]: 14, Pending(0)

default 12:51:53.591366 +0200 securityd ocsp responder: (null) did not include status of requested cert

default 12:51:53.601973 +0200 cloudd TIC TLS Trust Result [149:0x15ff72350]: 0

default 12:51:53.775506 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/Frameworks/CoreTelephony.framework'

default 12:51:53.864027 +0200 cloudd TIC TLS Event [149:0x15ff72350]: 20, Pending(0)

default 12:51:53.871118 +0200 cloudd TIC TCP Conn Event [149:0x15ff72350]: 8 Err(0)

default 12:51:53.872066 +0200 cloudd TIC TLS Handshake Complete [149:0x15ff72350]

default 12:51:53.876045 +0200 cloudd [Request 0x15fdf1c50] requestForEstablishedConnection

default 12:51:54.207342 +0200 locationd Incrementing METs -- mets:<private> metsFromGrade:<private>

default 12:51:54.232051 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client 'com.apple.HealthKit'

default 12:51:54.297083 +0200 cloudd [Request 0x15fdf1c50] URLSession:dataTask:didReceiveResponse:completionHandler:

default 12:51:54.312535 +0200 cloudd [Request 0x15fdf1c50] URLSession:dataTask:didReceiveData:

default 12:51:54.317248 +0200 cloudd [Request 0x15fdf1c50] URLSession:task:didCompleteWithError:

default 12:51:54.328169 +0200 cloudd [Operation 0x161014440] Initialized with context 0x1613711b0. Background: 0, cellular: 1, QOS: 0x19

default 12:51:54.331329 +0200 cloudd [Request 0x15fdf1c50] Finishing request with no error

default 12:51:54.333169 +0200 cloudd [Operation 0x161014440] Starting operation

default 12:51:54.337481 +0200 cloudd [Operation 0x16121d6a0] Request 0x0 set on operation

default 12:51:54.369610 +0200 cloudd [Operation 0x16121d6a0] Operation transitioning from state 2 (cancelled=0, stop=0, error=0)

default 12:51:54.370391 +0200 cloudd [Operation 0x161052bb0] Initialized with context 0x1613711b0. Background: 0, cellular: 1, QOS: 0x19

default 12:51:54.370958 +0200 cloudd [Operation 0x16121d6a0] Operation is now in state 3

default 12:51:54.371536 +0200 cloudd [Operation 0x161052bb0] Starting operation

default 12:51:54.380152 +0200 cloudd [Operation 0x161052bb0] Operation transitioning from state 1 (cancelled=0, stop=0, error=0)

default 12:51:54.383422 +0200 cloudd [Operation 0x161052bb0] Operation is now in state 2

default 12:51:54.384803 +0200 cloudd [Operation 0x161052bb0] Operation transitioning from state 2 (cancelled=0, stop=0, error=0)

default 12:51:54.387218 +0200 cloudd [Operation 0x161052bb0] Operation is now in state 3

default 12:51:54.422954 +0200 cloudd #fc63cded ACSMightCurrentNetworkHaveCachingServer(options={

capabilities = {

import = 1;

namespaces = 1;

personalCaching = 1;

};

quickMiss = 1;

"x-apple-persistent-identifier" = 2e04;

}, callbackQueue=0x0, callback=0x16e8297e8)

default 12:51:54.433351 +0200 cloudd #fc63cded ACSMightCurrentNetworkHaveCachingServer -> [new] mightHave 0, error (null), elapsed 0.013

default 12:51:54.435790 +0200 cloudd HttpSession <MMCSHTTPSession: 0x15ff51c40><uuid:C8B3A3A4-DCB9-4483-A9A6-55AE9831A51B session:default, z:foreground, adaptiveReadTimeout:3, adaptiveWriteTimeout:3>

default 12:51:54.436896 +0200 cloudd HttpURL (https://p59-content.icloud.com:443/11593352801/authorizeGet)

default 12:51:54.440445 +0200 cloudd RequestHeader (x-apple-request-uuid:D13C9DDD-B7C9-4C8E-A93B-B4276DA4E544)

default 12:51:54.443866 +0200 coreduetd Metering Update disabled because of App Refresh disabled

default 12:51:54.447605 +0200 cloudd TIC TCP Conn Start [150:0x15ff0fa20]

default 12:51:54.660681 +0200 locationd #warning no watchdog event from com.apple.springboard, deleting

default 12:51:54.661113 +0200 locationd Client com.apple.springboard disconnected

default 12:51:54.666115 +0200 locationd #warning no watchdog event from com.apple.locationd, deleting

default 12:51:54.666549 +0200 locationd Client com.apple.locationd disconnected

default 12:51:54.670615 +0200 locationd Client com.apple.springboard connected

default 12:51:54.671141 +0200 locationd getClientEffectiveRegistrationResult, /System/Library/CoreServices/SpringBoard.app/SpringBoard, com.apple.springboard, , CLClientRegistrationResult, kCLClientRegistrationResultFailedUnavailable, CLCommonLocationServicesEnabled, 1

default 12:51:54.671556 +0200 locationd message 'kCLConnectionMessageMotionActivityUpdate' received from client 'com.apple.springboard'

default 12:51:54.672229 +0200 locationd Client com.apple.springboard (0x11e0d8400) is subscribing to notification kCLConnectionMessageMotionActivityUpdate

default 12:51:54.673828 +0200 locationd Client com.apple.locationd connected

default 12:51:54.674129 +0200 locationd allowing internal executable com.apple.locationd

default 12:51:54.674317 +0200 locationd getClientEffectiveRegistrationResult, /usr/libexec/routined, com.apple.locationd, , CLClientRegistrationResult, kCLClientRegistrationResultAllowedAlways, CLCommonLocationServicesEnabled, 1

default 12:51:54.674997 +0200 locationd allowing internal executable com.apple.locationd

default 12:51:54.675138 +0200 locationd getClientEffectiveRegistrationResult, /usr/libexec/routined, com.apple.locationd, , CLClientRegistrationResult, kCLClientRegistrationResultAllowedAlways, CLCommonLocationServicesEnabled, 1

default 12:51:54.676080 +0200 locationd message 'kCLConnectionMessageMotionActivityUpdate' received from client 'com.apple.locationd'

default 12:51:54.676542 +0200 locationd Client com.apple.locationd (0x11e80a800) is subscribing to notification kCLConnectionMessageMotionActivityUpdate

default 12:51:54.956769 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/WifiCalling.bundle'

default 12:51:54.986037 +0200 CommCenter QMI: Svc=0xe2(BSP) Req MsgId=0xe002 Bin=[<private>]

default 12:51:55.045163 +0200 CommCenter QMI: Svc=0xe2(BSP) Resp MsgId=0xe002 Bin=[<private>]

default 12:51:55.047037 +0200 CommCenter #watchdog #I Callback Watchdog: checkin 3504

default 12:51:55.047358 +0200 CommCenter #watchdog #I Server Watchdog: checkin 3504

default 12:51:56.147853 +0200 cloudd TIC TCP Conn Event [150:0x15ff0fa20]: 1 Err(0)

default 12:51:56.148646 +0200 cloudd TIC TCP Conn Connected [150:0x15ff0fa20]: Err(0)

default 12:51:56.149769 +0200 cloudd TIC Enabling TLS [150:0x15ff0fa20]

default 12:51:56.386797 +0200 cloudd TIC TLS Event [150:0x15ff0fa20]: 2, Pending(0)

default 12:51:56.411914 +0200 locationd {"msg":"client getting effective client name", "clientName":"/usr/sbin/wifid", "bundleId":"", "bundlePath":"/System/Library/PrivateFrameworks/MobileWiFi.framework"}

default 12:51:56.423591 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/PrivateFrameworks/MobileWiFi.framework'

default 12:51:56.430322 +0200 cloudd TIC TLS Event [150:0x15ff0fa20]: 11, Pending(0)

default 12:51:56.432162 +0200 cloudd TIC TLS Event [150:0x15ff0fa20]: 22, Pending(0)

default 12:51:56.434473 +0200 cloudd TIC TLS Event [150:0x15ff0fa20]: 12, Pending(0)

default 12:51:56.435296 +0200 cloudd TIC TLS Event [150:0x15ff0fa20]: 14, Pending(0)

default 12:51:56.447459 +0200 cloudd could not disable pinning: not an internal release

default 12:51:56.447935 +0200 cloudd could not enable test cert: not an internal release

default 12:51:56.471377 +0200 securityd ocsp responder: (null) did not include status of requested cert

default 12:51:56.483129 +0200 cloudd TIC TLS Trust Result [150:0x15ff0fa20]: 0

default 12:51:56.761230 +0200 identityservicesd calling continuityDidDiscoverType:Activity withData:<private> fromPeer:<private>

error 12:51:56.774248 +0200 sharingd SecItemCopyMatching baseDict failed with error -25300

default 12:51:56.775158 +0200 sharingd No current key to decrypt advertisement from E4531DE6-C9AE-41C0-859D-278FD491CFB2 with rawAdvertisementData <086b17ecc5f41159d467e374772a>. Requesting key

error 12:51:56.780430 +0200 sharingd SecItemCopyMatching baseDict failed with error -25300

default 12:51:56.780548 +0200 sharingd SDActivityPayloadManager: BUDGET BLOCK: Only 2m21s since we last requested a key from E4531DE6-C9AE-41C0-859D-278FD491CFB2. Must wait another 38s

default 12:51:56.781236 +0200 cloudd TIC TLS Event [150:0x15ff0fa20]: 20, Pending(0)

default 12:51:56.786948 +0200 cloudd TIC TCP Conn Event [150:0x15ff0fa20]: 8 Err(0)

default 12:51:56.787166 +0200 cloudd TIC TLS Handshake Complete [150:0x15ff0fa20]

default 12:51:56.978995 +0200 CommCenter QMI: Svc=0xe2(BSP) Req MsgId=0xe002 Bin=[<private>]

default 12:51:57.045584 +0200 CommCenter QMI: Svc=0xe2(BSP) Resp MsgId=0xe002 Bin=[<private>]

default 12:51:57.057400 +0200 Mxxxxxx TIC TCP Conn Cancel [10:0x174387290]

default 12:51:57.058334 +0200 Mxxxxxx __nw_socket_service_writes_block_invoke sendmsg(fd 32, 31 bytes): socket has been closed

default 12:51:57.100680 +0200 cloudd HttpStatus (HTTP/1.1 200 no error)

default 12:51:57.101404 +0200 cloudd ResponseHeader (X-Apple-Request-UUID:D13C9DDD-B7C9-4C8E-A93B-B4276DA4E544)

default 12:51:57.101865 +0200 cloudd ResponseHeader (Via:xrail:st13p00ic-zteu25283501:8301:17E107:grp62, icloudedge:se03p01ic-zteu011122:7401:18RC19:Seattle)

default 12:51:57.102570 +0200 cloudd ResponseHeader (Server:AppleHttpServer/2f080fc0)

default 12:51:57.104121 +0200 cloudd ResponseHeader (X-Responding-Instance:content.15900504.st42p59ic-tyfb03210801:8004.1804B55)

default 12:51:57.108148 +0200 cloudd Observed 0.0029 Mbps over 2.6728 seconds for 974 bytes. 0.0111 seconds in queue.

default 12:51:57.112015 +0200 cloudd PutComplete at Edge Protocol : false

default 12:51:57.119832 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:0.0000 err:(null)

error 12:51:57.196662 +0200 cloudd Unregistering item without an asset handle for itemID=1847

default 12:51:57.199506 +0200 cloudd getItemReaderWriterForItemCallback did not succeed

default 12:51:57.281101 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:0.9901 err:(null)

default 12:51:57.317777 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/TimeZone.bundle'

default 12:51:57.319322 +0200 cloudd itemId:1849 local fulfillment took 0.1316 seconds for 9106292 bytes. Validated for Resume (0 bytes), Resumed (0 bytes), Fullfilled Locally (9106292 bytes)

default 12:51:57.320072 +0200 cloudd Renaming <private> to <private> for item 1849

default 12:51:57.321417 +0200 cloudd itemId 1849 completed

default 12:51:57.348572 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:0.9901 err:(null)

default 12:51:57.357961 +0200 cloudd [Operation 0x161052bb0] Operation transitioning from state 3 (cancelled=0, stop=0, error=0)

default 12:51:57.360100 +0200 cloudd [Operation 0x161052bb0] Operation is now in state 4294967295

default 12:51:57.367038 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:1.0000 err:(null)

default 12:51:57.380958 +0200 cloudd [Operation 0x16121d6a0] Operation transitioning from state 3 (cancelled=0, stop=0, error=0)

default 12:51:57.384058 +0200 cloudd [Operation 0x16121d6a0] Operation is now in state 4294967295

default 12:51:57.449212 +0200 Mxxxxxx TIC TCP Conn Cancel [7:0x17419ee00]

default 12:51:57.451957 +0200 Mxxxxxx __nw_socket_service_writes_block_invoke sendmsg(fd 27, 31 bytes): socket has been closed

default 12:51:57.517534 +0200 assetsd New connection 0x103d0ab70 (pid = 1091)

default 12:51:57.519937 +0200 kernel SandboxViolation: Mxxxxxx(1091) deny(1) file-read-metadata /private/var/mobile/Media/PhotoData/Photos.sqlite

default 12:51:57.522500 +0200 kernel SandboxViolation: Mxxxxxx(1091) deny(1) file-read-metadata /private/var/mobile/Media/PhotoData/Photos.sqlite

default 12:51:57.579140 +0200 kernel SandboxViolation: Mxxxxxx(1091) deny(1) file-read-metadata /private/var/mobile/Media/PhotoData/Photos.sqlite

default 12:51:57.586547 +0200 Mxxxxxx Load database will create database: database is missing

default 12:51:57.586731 +0200 Mxxxxxx Issuing request for updated photo library database

default 12:51:57.587649 +0200 Mxxxxxx Load database will create database: database is missing

default 12:51:57.587885 +0200 Mxxxxxx Issuing request for updated photo library database

default 12:51:57.591578 +0200 Mxxxxxx Load database will create database: database is missing

default 12:51:57.591727 +0200 Mxxxxxx Issuing request for updated photo library database

default 12:51:57.592048 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:1.0000 err:(null)

default 12:51:58.027421 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/Traffic.bundle'

default 12:51:58.030548 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/MotionCalibration.bundle'

default 12:51:58.033573 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/CompassCalibration.bundle'

default 12:51:58.035448 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/TimeZone.bundle'

default 12:51:58.037759 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/MotionCalibration.bundle'

default 12:51:58.039987 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/MotionCalibration.bundle'

default 12:51:58.041228 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/Routine.bundle'

default 12:51:58.043617 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/AppSuggestions.bundle'

default 12:51:58.045080 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/AppGenius.bundle'

default 12:51:59.154020 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/Traffic.bundle'

default 12:51:59.156626 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/Routine.bundle'

default 12:51:59.157906 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client 'com.apple.AppStore'

default 12:51:59.158721 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/AppGenius.bundle'

default 12:51:59.159629 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/MotionCalibration.bundle'

default 12:51:59.164205 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/Traffic.bundle'

default 12:51:59.165151 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/Routine.bundle'

default 12:51:59.173527 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/Traffic.bundle'

default 12:51:59.175865 +0200 CommCenter QMI: Svc=0xe2(BSP) Req MsgId=0xe002 Bin=[<private>]

default 12:51:59.185416 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/LocationBundles/AppGenius.bundle'

default 12:51:59.248206 +0200 CommCenter QMI: Svc=0xe2(BSP) Resp MsgId=0xe002 Bin=[<private>]

default 12:51:59.261731 +0200 locationd Incrementing METs -- mets:<private> metsFromGrade:<private>

default 12:51:59.642522 +0200 CommCenter QMI: Svc=0xe7(ELQM) Ind MsgId=0x0002 Bin=[<private>]

default 12:51:59.650329 +0200 symptomsd eLQM: Posting RRC change notification with label = kNotificationCellLinkStateChange, state = 0, bitmask = 2, info = {

Detail = 0;

State = 0;

}

default 12:51:59.651530 +0200 symptomsd eLQM: Updated cell states (payload = <01020000 00>): (LQM = 100, RRC = 0, INTF = 1)

default 12:51:59.671434 +0200 symptomsd RRC State change

default 12:51:59.672046 +0200 symptomsd 0x131e560e0 foreground: 1 primary: 0 for noi: NOI: v:0 type:Cell, isAny:yes, isBuiltin:no, loi:-1, flags:0

default 12:51:59.674568 +0200 symptomsd 0x131e59ba0 observed discretionaryTrafficInvited of object NOI: v:0 type:Cell, isAny:yes, isBuiltin:no, loi:-1, flags:0, partial update to pid: 57

default 12:51:59.675107 +0200 symptomsd 0x131e4cea0 observed discretionaryTrafficInvited of object NOI: v:0 type:Cell, isAny:yes, isBuiltin:no, loi:-1, flags:0, partial update to pid: 85

default 12:51:59.675907 +0200 symptomsd 0x131e63f40 observed discretionaryTrafficInvited of object NOI: v:0 type:Cell, isAny:yes, isBuiltin:no, loi:-1, flags:0, partial update to pid: 92

default 12:51:59.676516 +0200 locationd message 'kCLConnectionMessageOnBodyDetection' received from client '/System/Library/Frameworks/CoreTelephony.framework/Support/CommCenter'

default 12:51:59.676955 +0200 CommCenter QMI: Svc=0xe2(BSP) Ind MsgId=0xe006 Bin=[<private>]

default 12:51:59.677398 +0200 symptomsd RRC Update to OFF. mach time: 1261983243547 <0x131e560e0> (NOI: v:0 type:Cell, isAny:yes, isBuiltin:no, loi:-1, flags:0)

default 12:51:59.678709 +0200 symptomsd _lastDisconnectTimestamp: 1261983243547

default 12:51:59.679293 +0200 locationd Client /System/Library/Frameworks/CoreTelephony.framework/Support/CommCenter (0x11e0b1400) is unsubscribing to notification kCLConnectionMessageOnBodyDetection

default 12:51:59.684420 +0200 symptomsd 0x131e560e0 foreground: 1 primary: 0 for noi: NOI: v:0 type:Cell, isAny:yes, isBuiltin:no, loi:-1, flags:0

default 12:51:59.685249 +0200 symptomsd AWD RRC Metric: noi.isAny with no foregroundActivity flag became OFF (plugged in)

default 12:51:59.686212 +0200 symptomsd 0x131e58100 foreground: 1 primary: 0 for noi: NOI: v:0 type:Cell, isAny:yes, isBuiltin:no, loi:-1, flags:1

default 12:51:59.686370 +0200 locationd Client /System/Library/Frameworks/CoreTelephony.framework/Support/CommCenter disconnected

default 12:51:59.686870 +0200 symptomsd 0x131e59380 foreground: 1 primary: 0 for noi: NOI: v:0 type:Cell, isAny:no, isBuiltin:yes, loi:0, flags:0

default 12:51:59.690317 +0200 DuetHeuristic-BM Trigger: <private> is now [0]

default 12:51:59.694449 +0200 CommCenter QMI: Svc=0x01(WDS) Ind MsgId=0x0001 Bin=['01 10 00 80 01 0B 04 4D 0A 01 00 04 00 18 01 00 01']

default 12:51:59.695704 +0200 CommCenter #I dor.QMIDormancyCommandDriver: ___ZN8dormancy24QMIDormancyCommandDriver20handleEventReportIndERKN3wds11EventReport10IndicationE_block_invoke: EventReportInd, dormancy status: kDormant

default 12:51:59.696101 +0200 CommCenter #I DormancyStatus event, success:true, status:kDormant

default 12:51:59.696376 +0200 CommCenter QMI: Svc=0x01(WDS) Ind MsgId=0x0001 Bin=['01 10 00 80 01 01 04 79 0C 01 00 04 00 18 01 00 01']

default 12:51:59.696551 +0200 CommCenter #I DATA.QMIDriver:CMD: handleWdsEventReportInd_sync: Received WDS Set Event Report Indications

default 12:51:59.696768 +0200 CommCenter #I DATA.QMIDriver:CMD: processWdsTlvDormancyStatus: Dormancy status: kDormancyStatusDormant

default 12:51:59.697071 +0200 CommCenter #I DATA.BBDriver: setDormancy: from false to true

default 12:51:59.697165 +0200 CommCenter #I DATA.QMIDriver:CMD: sendWdsGetCurrentDataBearerTechReq_sync: Getting current data bearer technology

default 12:51:59.697342 +0200 CommCenter QMI: Svc=0x01(WDS) Req MsgId=0x0044 Bin=[<private>]

default 12:51:59.698331 +0200 CommCenter QMI: Svc=0x01(WDS) Resp MsgId=0x0044 Bin=[<private>]

default 12:51:59.698475 +0200 CommCenter #I DATA.QMIDriver:CMD: ___ZN20QMIDataCommandDriver39sendWdsGetCurrentDataBearerTechReq_syncEv_block_invoke: Response to GetCurrentDataBearerTech received

default 12:51:59.698677 +0200 CommCenter #I DATA.QMIDriver:CMD: ___ZN20QMIDataCommandDriver39sendWdsGetCurrentDataBearerTechReq_syncEv_block_invoke: Data Bearer Technology status: current network (2) rat mask (1) service option mask (0)

default 12:51:59.698873 +0200 CommCenter #I DATA.BBDriver: notifyDataBearer: kDataWirelessTechnologyUMTS: fDormancy true sending kRadioTransmitDCH(TxOff)

default 12:51:59.698998 +0200 CommCenter #I DATA.Connection:WirelessModemAuthentication: handleDCHState: restEvent: dch=0

default 12:51:59.699185 +0200 CommCenter #I DATA.Connection:WirelessModemTraffic: handleDCHState: restEvent: dch=0

default 12:51:59.699346 +0200 CommCenter #I DATA.Connection:AppleWirelessDiagnostics: handleDCHState: restEvent: dch=0

default 12:51:59.699664 +0200 CommCenter #I DATA.Connection:DataTest: handleDCHState: restEvent: dch=0

default 12:51:59.699811 +0200 CommCenter #I DATA.Connection:OTAActivation: handleDCHState: restEvent: dch=0

default 12:51:59.699899 +0200 CommCenter #I DATA.Connection:OTAInternet: handleDCHState: restEvent: dch=0

default 12:51:59.700104 +0200 CommCenter #I DATA.Connection:ZeroRated: handleDCHState: restEvent: dch=0

default 12:51:59.700443 +0200 CommCenter #I DATA.Connection:Provisioning: handleDCHState: restEvent: dch=0

default 12:51:59.700659 +0200 CommCenter #I DATA.Connection:EmLoc: handleDCHState: restEvent: dch=0

default 12:51:59.700892 +0200 CommCenter #I DATA.Connection:3GFaceTimeAuthentication: handleDCHState: restEvent: dch=0

default 12:51:59.701019 +0200 CommCenter #I DATA.Connection:BootstrapRoamingInternetBypass: handleDCHState: restEvent: dch=0

default 12:51:59.701176 +0200 CommCenter #I DATA.Connection:UT: handleDCHState: restEvent: dch=0

default 12:51:59.701325 +0200 CommCenter #I DATA.Connection:Internet: handleDCHState: restEvent: dch=0

default 12:51:59.701452 +0200 CommCenter #I DATA.Connection:VVM: handleDCHState: restEvent: dch=0

default 12:51:59.701709 +0200 CommCenter #I DATA.Connection:Em: handleDCHState: restEvent: dch=0

default 12:51:59.701914 +0200 CommCenter #I DATA.Connection:Bootstrap: handleDCHState: restEvent: dch=0

default 12:51:59.702042 +0200 CommCenter #I DATA.Connection:3GFaceTimeTraffic: handleDCHState: restEvent: dch=0

default 12:51:59.702231 +0200 CommCenter #I DATA.Connection:OMADM: handleDCHState: restEvent: dch=0

default 12:51:59.702395 +0200 CommCenter #I DATA.Connection:iw5: handleDCHState: restEvent: dch=0

default 12:51:59.702591 +0200 CommCenter #I DATA.Connection:InternalDataProbe: handleDCHState: restEvent: dch=0

default 12:51:59.702765 +0200 CommCenter #I DATA.Connection:PushEmail: handleDCHState: restEvent: dch=0

default 12:51:59.702940 +0200 CommCenter #I DATA.Connection:MMS: handleDCHState: restEvent: dch=0

default 12:51:59.703120 +0200 CommCenter #I DATA.Connection:EntitlementTraffic: handleDCHState: restEvent: dch=0

default 12:51:59.703883 +0200 calaccessd 2018-03-19 12:51:59 +0200 calaccessd[127]: Interface manager: WWAN radio power level notification; DCH status changed to inactive

default 12:51:59.704073 +0200 imagent 2018-03-19 12:51:59 +0200 imagent[65]: Interface manager: WWAN radio power level notification; DCH status changed to inactive

default 12:51:59.704246 +0200 DuetHeuristic-BM 2018-03-19 12:51:59 +0200 DuetHeuristic-BM[105]: Interface manager: WWAN radio power level notification; DCH status changed to inactive

default 12:51:59.704422 +0200 DuetHeuristic-BM 2018-03-19 12:51:59 +0200 DuetHeuristic-BM[105]: <PCInterfaceUsabilityMonitor: 0x1002396c0> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.704597 +0200 DuetHeuristic-BM 2018-03-19 12:51:59 +0200 DuetHeuristic-BM[105] com.apple.Duet.DuetActivityScheduler.ActivityEvaluationTimer: <PCPersistentTimer: 0x1002780c0> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.704732 +0200 DuetHeuristic-BM 2018-03-19 12:51:59 +0200 DuetHeuristic-BM[105] com.apple.Duet.DuetActivityScheduler.ActivityEvaluationTimer: Last system wake date (2018-03-19 12:19:02 +0200) was longer than half of the timer duration, so setting minimum fire date to fire date.

default 12:51:59.704884 +0200 DuetHeuristic-BM 2018-03-19 12:51:59 +0200 DuetHeuristic-BM[105] com.apple.Duet.DuetActivityScheduler.ActivityEvaluationTimer: <PCPersistentTimer: 0x1002780c0> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.705010 +0200 DuetHeuristic-BM 2018-03-19 12:51:59 +0200 DuetHeuristic-BM[105] com.apple.Duet.DuetActivityScheduler.ActivityEvaluationTimer: <PCPersistentTimer: 0x1002780c0> Calculated minimum fire date [2018-03-19 12:59:34 +0200] (100%) with fire date [2018-03-19 12:59:34 +0200], start date [2018-03-19 12:49:09 +0200], minimum early fire proportion 0.807479, power state detection supported: yes, in high power state: no

default 12:51:59.705227 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63]: Interface manager: WWAN radio power level notification; DCH status changed to inactive

default 12:51:59.705456 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63]: <PCInterfaceUsabilityMonitor: 0x11f201d60> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.705586 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] HarvestUploadTimer: <PCPersistentTimer: 0x11f2b2140> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.705737 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] HarvestUploadTimer: <PCPersistentTimer: 0x11f2b2140> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.705863 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] HarvestUploadTimer: <PCPersistentTimer: 0x11f2b2140> Calculated minimum fire date [2018-03-19 19:58:11 +0200] (90%) with fire date [2018-03-19 21:09:42 +0200], start date [2018-03-19 09:14:30 +0200], minimum early fire proportion 0.9, power state detection supported: yes, in high power state: no

default 12:51:59.706030 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63]: <PCInterfaceUsabilityMonitor: 0x11f201d60> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.706300 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] FenceDownloadTimer: <PCPersistentTimer: 0x11dffb920> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.707057 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] FenceDownloadTimer: <PCPersistentTimer: 0x11dffb920> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.707138 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] FenceDownloadTimer: <PCPersistentTimer: 0x11dffb920> Calculated minimum fire date [2018-03-19 21:40:42 +0200] (90%) with fire date [2018-03-19 22:52:42 +0200], start date [2018-03-19 10:52:42 +0200], minimum early fire proportion 0.9, power state detection supported: yes, in high power state: no

default 12:51:59.707342 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63]: <PCInterfaceUsabilityMonitor: 0x11f201d60> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.707422 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] CellLocDelayedCellLocationPropagationTimer: <PCPersistentTimer: 0x11dff8210> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.707615 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] CellLocDelayedCellLocationPropagationTimer: Last system wake date (2018-03-19 12:19:02 +0200) was longer than half of the timer duration, so setting minimum fire date to fire date.

default 12:51:59.707804 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] CellLocDelayedCellLocationPropagationTimer: <PCPersistentTimer: 0x11dff8210> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.707966 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] CellLocDelayedCellLocationPropagationTimer: <PCPersistentTimer: 0x11dff8210> Calculated minimum fire date [2018-03-19 12:52:29 +0200] (100%) with fire date [2018-03-19 12:52:29 +0200], start date [2018-03-19 12:47:29 +0200], minimum early fire proportion 0.9, power state detection supported: yes, in high power state: no

default 12:51:59.708092 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63]: <PCInterfaceUsabilityMonitor: 0x11f201d60> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.708326 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] WifiAWDTimer: <PCPersistentTimer: 0x11f24ef70> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.708458 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] WifiAWDTimer: <PCPersistentTimer: 0x11f24ef70> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.708822 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] WifiAWDTimer: <PCPersistentTimer: 0x11f24ef70> Calculated minimum fire date [2018-03-19 19:51:17 +0200] (90%) with fire date [2018-03-19 22:15:17 +0200], start date [2018-03-18 22:15:17 +0200], minimum early fire proportion 0.9, power state detection supported: yes, in high power state: no

default 12:51:59.709056 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63]: <PCInterfaceUsabilityMonitor: 0x11f201d60> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.709217 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] HarvestPruneTimer: <PCPersistentTimer: 0x11f055070> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.709410 +0200 nanoregistryd 2018-03-19 12:51:59 +0200 nanoregistryd[95]: Interface manager: WWAN radio power level notification; DCH status changed to inactive

default 12:51:59.709583 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] HarvestPruneTimer: <PCPersistentTimer: 0x11f055070> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.709810 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] HarvestPruneTimer: <PCPersistentTimer: 0x11f055070> Calculated minimum fire date [2018-03-19 19:19:34 +0200] (90%) with fire date [2018-03-19 21:07:34 +0200], start date [2018-03-19 03:07:34 +0200], minimum early fire proportion 0.9, power state detection supported: yes, in high power state: no

default 12:51:59.709970 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63]: <PCInterfaceUsabilityMonitor: 0x11f201d60> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.710098 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] TimeZoneManager.ActiveModeTimer: <PCPersistentTimer: 0x11f0b6f70> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.710264 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] TimeZoneManager.ActiveModeTimer: Last system wake date (2018-03-19 12:19:02 +0200) was longer than half of the timer duration, so setting minimum fire date to fire date.

default 12:51:59.710543 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] TimeZoneManager.ActiveModeTimer: <PCPersistentTimer: 0x11f0b6f70> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.710731 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] TimeZoneManager.ActiveModeTimer: <PCPersistentTimer: 0x11f0b6f70> Calculated minimum fire date [2018-03-19 13:27:29 +0200] (75%) with fire date [2018-03-19 13:42:29 +0200], start date [2018-03-19 12:42:29 +0200], minimum early fire proportion 0.75, power state detection supported: yes, in high power state: no

default 12:51:59.710985 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63]: <PCInterfaceUsabilityMonitor: 0x11f201d60> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.711115 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] CompassDatabaseDaemonClearBiasTimer: <PCPersistentTimer: 0x11dfa2880> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.711289 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] CompassDatabaseDaemonClearBiasTimer: <PCPersistentTimer: 0x11dfa2880> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.711417 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] CompassDatabaseDaemonClearBiasTimer: <PCPersistentTimer: 0x11dfa2880> Calculated minimum fire date [2018-03-20 14:13:06 +0200] (90%) with fire date [2018-03-21 02:13:06 +0200], start date [2018-03-16 02:13:06 +0200], minimum early fire proportion 0.9, power state detection supported: yes, in high power state: no

default 12:51:59.711499 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63]: <PCInterfaceUsabilityMonitor: 0x11f201d60> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.711689 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] NetworkLocationPurgeTimer: <PCPersistentTimer: 0x11f15db10> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.711872 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] NetworkLocationPurgeTimer: <PCPersistentTimer: 0x11f15db10> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.712070 +0200 locationd 2018-03-19 12:51:59 +0200 locationd[63] NetworkLocationPurgeTimer: <PCPersistentTimer: 0x11f15db10> Calculated minimum fire date [2018-03-19 13:14:16 +0200] (90%) with fire date [2018-03-19 13:44:16 +0200], start date [2018-03-19 08:44:16 +0200], minimum early fire proportion 0.9, power state detection supported: yes, in high power state: no

default 12:51:59.712271 +0200 UserEventAgent 2018-03-19 12:51:59 +0200 UserEventAgent[25]: Interface manager: WWAN radio power level notification; DCH status changed to inactive

default 12:51:59.712474 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85]: Interface manager: WWAN radio power level notification; DCH status changed to inactive

default 12:51:59.712763 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85]: <PCInterfaceUsabilityMonitor: 0x1003927e0> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.712966 +0200 UserEventAgent 2018-03-19 12:51:59 +0200 UserEventAgent[25]: <PCInterfaceUsabilityMonitor: 0x107ebdb00> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.713139 +0200 UserEventAgent 2018-03-19 12:51:59 +0200 UserEventAgent[25] BTA-PeriodicConditionMonitor: <PCPersistentTimer: 0x107eb6e30> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.713402 +0200 UserEventAgent 2018-03-19 12:51:59 +0200 UserEventAgent[25] BTA-PeriodicConditionMonitor: Last system wake date (2018-03-19 12:19:02 +0200) was longer than half of the timer duration, so setting minimum fire date to fire date.

default 12:51:59.713602 +0200 UserEventAgent 2018-03-19 12:51:59 +0200 UserEventAgent[25] BTA-PeriodicConditionMonitor: <PCPersistentTimer: 0x107eb6e30> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.713762 +0200 UserEventAgent 2018-03-19 12:51:59 +0200 UserEventAgent[25] BTA-PeriodicConditionMonitor: <PCPersistentTimer: 0x107eb6e30> Calculated minimum fire date [2018-03-19 13:18:09 +0200] (45%) with fire date [2018-03-19 13:51:09 +0200], start date [2018-03-19 12:51:09 +0200], minimum early fire proportion 0.45, power state detection supported: yes, in high power state: no

default 12:51:59.713893 +0200 UserEventAgent 2018-03-19 12:51:59 +0200 UserEventAgent[25]: <PCInterfaceUsabilityMonitor: 0x107ebdb00> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.714049 +0200 UserEventAgent 2018-03-19 12:51:59 +0200 UserEventAgent[25] MobileBackupRegularWake: <PCPersistentTimer: 0x107dbf2e0> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.714337 +0200 UserEventAgent 2018-03-19 12:51:59 +0200 UserEventAgent[25] MobileBackupRegularWake: <PCPersistentTimer: 0x107dbf2e0> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.714557 +0200 UserEventAgent 2018-03-19 12:51:59 +0200 UserEventAgent[25] MobileBackupRegularWake: Forcing timer alignment to fire date [2018-03-19 13:06:45 +0200]

default 12:51:59.714706 +0200 UserEventAgent 2018-03-19 12:51:59 +0200 UserEventAgent[25] MobileBackupRegularWake: <PCPersistentTimer: 0x107dbf2e0> Calculated minimum fire date [2018-03-19 13:06:45 +0200] (16.1394%) with fire date [2018-03-20 09:14:20 +0200], start date [2018-03-19 09:14:20 +0200], minimum early fire proportion 0, power state detection supported: yes, in high power state: no

default 12:51:59.714857 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85] com.apple.apsd(sandbox.push.apple.com)-WWAN: <PCPersistentTimer: 0x100376cf0> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.715014 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85]: <APSCourier: 0x10040cf00> <PCInterfaceMonitor: 0x100411560> interface radio hotness changed to NO

default 12:51:59.715118 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85]: <APSTopicManager: 0x10031a3f0> isPowerEfficientToSendFilter changed to NO

default 12:51:59.715347 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85]: <APSCourier: 0x1004b1f60> <PCInterfaceMonitor: 0x100411560> interface radio hotness changed to NO

default 12:51:59.715530 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85]: <APSTopicManager: 0x1003a7800> isPowerEfficientToSendFilter changed to NO

default 12:51:59.715636 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85] com.apple.apsd(sandbox.push.apple.com)-WWAN: Last system wake date (2018-03-19 12:19:02 +0200) was longer than half of the timer duration, so setting minimum fire date to fire date.

default 12:51:59.715865 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85] com.apple.apsd(sandbox.push.apple.com)-WWAN: <PCPersistentTimer: 0x100376cf0> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.716038 +0200 SpringBoard 2018-03-19 12:51:59 +0200 SpringBoard[57]: Interface manager: WWAN radio power level notification; DCH status changed to inactive

default 12:51:59.716257 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85] com.apple.apsd(sandbox.push.apple.com)-WWAN: Forcing timer alignment to fire date [2018-03-19 13:06:45 +0200]

default 12:51:59.716754 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85] com.apple.apsd(sandbox.push.apple.com)-WWAN: <PCPersistentTimer: 0x100376cf0> Calculated minimum fire date [2018-03-19 13:06:45 +0200] (53.1272%) with fire date [2018-03-19 13:19:59 +0200], start date [2018-03-19 12:51:43 +0200], minimum early fire proportion 0, power state detection supported: yes, in high power state: no

default 12:51:59.717146 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85]: <PCInterfaceUsabilityMonitor: 0x1003927e0> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.717643 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85] com.apple.apsd(push.apple.com)-NonCellular: <PCPersistentTimer: 0x10036df50> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.718089 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85] com.apple.apsd(push.apple.com)-NonCellular: Last system wake date (2018-03-19 12:19:02 +0200) was longer than half of the timer duration, so setting minimum fire date to fire date.

default 12:51:59.718383 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85] com.apple.apsd(push.apple.com)-NonCellular: <PCPersistentTimer: 0x10036df50> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.718516 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85] com.apple.apsd(push.apple.com)-NonCellular: <PCPersistentTimer: 0x10036df50> Calculated minimum fire date [2018-03-19 13:03:17 +0200] (100%) with fire date [2018-03-19 13:03:17 +0200], start date [2018-03-19 12:42:57 +0200], minimum early fire proportion 0, power state detection supported: yes, in high power state: no

default 12:51:59.718685 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85]: <PCInterfaceUsabilityMonitor: 0x1003927e0> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.718894 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85] com.apple.apsd(push.apple.com)-WWAN: <PCPersistentTimer: 0x1004ace50> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.719224 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85] com.apple.apsd(push.apple.com)-WWAN: Last system wake date (2018-03-19 12:19:02 +0200) was longer than half of the timer duration, so setting minimum fire date to fire date.

default 12:51:59.719733 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85] com.apple.apsd(push.apple.com)-WWAN: <PCPersistentTimer: 0x1004ace50> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.719987 +0200 apsd 2018-03-19 12:51:59 +0200 apsd[85] com.apple.apsd(push.apple.com)-WWAN: <PCPersistentTimer: 0x1004ace50> Calculated minimum fire date [2018-03-19 12:56:08 +0200] (100%) with fire date [2018-03-19 12:56:08 +0200], start date [2018-03-19 12:27:57 +0200], minimum early fire proportion 0, power state detection supported: yes, in high power state: no

default 12:51:59.720287 +0200 identityservicesd 2018-03-19 12:51:59 +0200 identityservicesd[51]: Interface manager: WWAN radio power level notification; DCH status changed to inactive

default 12:51:59.720442 +0200 identityservicesd 2018-03-19 12:51:59 +0200 identityservicesd[51]: <PCInterfaceUsabilityMonitor: 0x1008b18f0> [WWAN](pdp_ip0): isInterfaceUsable? YES reachable YES linkQuality 100 isNetworkCaptive? NO

default 12:51:59.720603 +0200 identityservicesd 2018-03-19 12:51:59 +0200 identityservicesd[51] com.apple.identityservices.registration-hbi: <PCPersistentTimer: 0x1008f5320> calculating _earlyFireDate. powerStateDetectionSupported = YES = (detectionSupported(YES) && (wwanIsUp(YES) || ! internetReachable(YES)))

default 12:51:59.720776 +0200 identityservicesd 2018-03-19 12:51:59 +0200 identityservicesd[51] com.apple.identityservices.registration-hbi: <PCPersistentTimer: 0x1008f5320> Device is plugged in, overriding earlyFireProportion to be 1.0

default 12:51:59.720908 +0200 identityservicesd 2018-03-19 12:51:59 +0200 identityservicesd[51] com.apple.identityservices.registration-hbi: <PCPersistentTimer: 0x1008f5320> Calculated minimum fire date [2018-04-21 19:33:47 +0300] (100%) with fire date [2018-04-21 19:33:47 +0300], start date [2018-03-19 11:30:53 +0200], minimum early fire proportion 1, power state detection supported: yes, in high power state: no

default 12:51:59.723670 +0200 symptomsd New RRC 0 when previous 1 from pdp_ip0, epoch interface pdp_ip0

error 12:51:59.726315 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 848)

error 12:51:59.726518 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.726672 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 890)

error 12:51:59.726814 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.726984 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 720)

error 12:51:59.727090 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.727274 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 722)

error 12:51:59.727499 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.727670 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 734)

error 12:51:59.727752 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.727988 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 858)

error 12:51:59.728264 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.728492 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 732)

error 12:51:59.728624 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.728835 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 10369)

error 12:51:59.729064 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.729223 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 2117)

error 12:51:59.729452 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.729585 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 860)

error 12:51:59.729741 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.729874 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 853)

error 12:51:59.730028 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.730255 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 10406)

error 12:51:59.730504 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.730658 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 10376)

error 12:51:59.730997 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.731392 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 860)

error 12:51:59.731929 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.735709 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 714)

error 12:51:59.735960 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.736363 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 968)

error 12:51:59.736798 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.737249 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 837)

error 12:51:59.737716 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.738051 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 726)

error 12:51:59.738397 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.738950 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 849)

error 12:51:59.739177 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.739637 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 720)

error 12:51:59.739991 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.740413 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 716)

error 12:51:59.740616 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.741041 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 722)

error 12:51:59.741386 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.741930 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 848)

error 12:51:59.742117 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.742612 +0200 coreduetd Data for key <private> does not fit in 693 bytes (it is 10360)

error 12:51:59.743053 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.743577 +0200 coreduetd Data for key <private> does not fit in 172 bytes (it is 728)

error 12:51:59.743814 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.744443 +0200 coreduetd Data for key <private> does not fit in 172 bytes (it is 714)

error 12:51:59.744733 +0200 coreduetd Serialized size exceeds shared memory capacity

error 12:51:59.745382 +0200 coreduetd Data for key <private> does not fit in 172 bytes (it is 739)

error 12:51:59.745627 +0200 coreduetd Serialized size exceeds shared memory capacity

default 12:51:59.846651 +0200 locationd message 'kCLConnectionMessageWatchdog' received from client '/System/Library/PrivateFrameworks/CoreParsec.framework'

default 12:52:00.241527 +0200 Mxxxxxx ***************** requestAVAssetForVideo END *****************

Replies  3
Boosts  0
Views  2.7k
Participants  2
shobi OP
Mar ’18

more details:

iOS 10.2.1 (but also reproducable in 11.2.6)

device: iPhone 6 16GB

0
shobi OP
Mar ’18

Reproduce on iPhone X, 11.2.6


here is the log


default 14:04:34.043534 +0200 Mxxxxxx ***************** requestAVAssetForVideo START *****************

default 14:04:34.048482 +0200 assertiond [Mxxxxxx:608] Attempting to acquire assertion for Mxxxxxx:608: <BKProcessAssertion: 0x10292dbc0; "Called by UIKit, from <redacted>" (finishTask:180s); id:…74A6B41AD7D4>

default 14:04:34.048679 +0200 assertiond [Mxxxxxx:608] Add assertion: <BKProcessAssertion: 0x10292dbc0; id: 608-5CE09D19-4E71-410E-A0B0-74A6B41AD7D4; name: "Called by UIKit, from <redacted>"; state: active; reason: finishTask; duration: 180.0s> {

owner = <BSProcessHandle: 0x102a12550; Mxxxxxx:608; valid: YES>;

flags = preventSuspend, preventIdleSleep, preventSuspendOnSleep;

}

default 14:04:34.048772 +0200 assertiond [Mxxxxxx:608] Activate assertion: <BKProcessAssertion: 0x10292dbc0; "Called by UIKit, from <redacted>" (finishTask:180s); id:…74A6B41AD7D4>

default 14:04:34.048910 +0200 assertiond [Mxxxxxx:608] dump all assertions HWM:7 (CPUMON check): {

<BKProcessAssertion: 0x10292d6a0; "Resume" (activation:inf); id:…41AFDC851ACA> [active]

<BKProcessAssertion: 0x102c1af70; "SKProductsRequest" (finishTask:180s); id:…73BA0A71A901> [active]

<BKProcessAssertion: 0x10292dbc0; "Called by UIKit, from <redacted>" (finishTask:180s); id:…74A6B41AD7D4> [active]

}

default 14:04:34.049131 +0200 assertiond Updating PowerAssertion on Mxxxxxx:608

default 14:04:34.050772 +0200 assertiond Client relinquished <BKProcessAssertion: 0x10292dbc0; "Called by UIKit, from <redacted>" (finishTask:180s); id:…74A6B41AD7D4>

default 14:04:34.050961 +0200 assertiond [Mxxxxxx:608] Deactivate assertion: <BKProcessAssertion: 0x10292dbc0; "Called by UIKit, from <redacted>" (finishTask:180s); id:…74A6B41AD7D4>

default 14:04:34.051060 +0200 assertiond [Mxxxxxx:608] dump all assertions HWM:7 (deactivateAssertion): {

<BKProcessAssertion: 0x10292d6a0; "Resume" (activation:inf); id:…41AFDC851ACA> [active]

<BKProcessAssertion: 0x102c1af70; "SKProductsRequest" (finishTask:180s); id:…73BA0A71A901> [active]

}

default 14:04:34.053044 +0200 assertiond [Mxxxxxx:608] dump all assertions HWM:7 (CPUMON check): {

<BKProcessAssertion: 0x10292d6a0; "Resume" (activation:inf); id:…41AFDC851ACA> [active]

<BKProcessAssertion: 0x102c1af70; "SKProductsRequest" (finishTask:180s); id:…73BA0A71A901> [active]

}

default 14:04:34.053325 +0200 assertiond Updating PowerAssertion on Mxxxxxx:608

default 14:04:34.053507 +0200 assertiond [Mxxxxxx:608] Attempting to acquire assertion for Mxxxxxx:608: <BKProcessAssertion: 0x102a16e90; "Called by UIKit, from <redacted>" (finishTask:180s); id:…8526F7256C09>

default 14:04:34.053695 +0200 assertiond [Mxxxxxx:608] Remove assertion: <BKProcessAssertion: 0x10292dbc0; "Called by UIKit, from <redacted>" (finishTask:180s); id:…74A6B41AD7D4>

default 14:04:34.053789 +0200 assertiond [Mxxxxxx:608] dump all assertions HWM:7 (CPUMON check): {

<BKProcessAssertion: 0x10292d6a0; "Resume" (activation:inf); id:…41AFDC851ACA> [active]

<BKProcessAssertion: 0x102c1af70; "SKProductsRequest" (finishTask:180s); id:…73BA0A71A901> [active]

}

default 14:04:34.054099 +0200 assertiond Updating PowerAssertion on Mxxxxxx:608

default 14:04:34.054324 +0200 assertiond -[BKAssertion dealloc] - <0x10292c0c0>

default 14:04:34.054423 +0200 assertiond [Mxxxxxx:608] Add assertion: <BKProcessAssertion: 0x102a16e90; id: 608-C9F9D7F7-917B-469C-A8BF-8526F7256C09; name: "Called by UIKit, from <redacted>"; state: active; reason: finishTask; duration: 180.0s> {

owner = <BSProcessHandle: 0x102a12550; Mxxxxxx:608; valid: YES>;

flags = preventSuspend, preventIdleSleep, preventSuspendOnSleep;

}

default 14:04:34.054471 +0200 assertiond [Mxxxxxx:608] Activate assertion: <BKProcessAssertion: 0x102a16e90; "Called by UIKit, from <redacted>" (finishTask:180s); id:…8526F7256C09>

default 14:04:34.054518 +0200 assertiond [Mxxxxxx:608] dump all assertions HWM:7 (CPUMON check): {

<BKProcessAssertion: 0x10292d6a0; "Resume" (activation:inf); id:…41AFDC851ACA> [active]

<BKProcessAssertion: 0x102c1af70; "SKProductsRequest" (finishTask:180s); id:…73BA0A71A901> [active]

<BKProcessAssertion: 0x102a16e90; "Called by UIKit, from <redacted>" (finishTask:180s); id:…8526F7256C09> [active]

}

default 14:04:34.054658 +0200 assertiond Updating PowerAssertion on Mxxxxxx:608

default 14:04:34.055058 +0200 assertiond Client relinquished <BKProcessAssertion: 0x102a16e90; "Called by UIKit, from <redacted>" (finishTask:180s); id:…8526F7256C09>

default 14:04:34.055800 +0200 assertiond [Mxxxxxx:608] Deactivate assertion: <BKProcessAssertion: 0x102a16e90; "Called by UIKit, from <redacted>" (finishTask:180s); id:…8526F7256C09>

default 14:04:34.055936 +0200 assertiond [Mxxxxxx:608] dump all assertions HWM:7 (deactivateAssertion): {

<BKProcessAssertion: 0x10292d6a0; "Resume" (activation:inf); id:…41AFDC851ACA> [active]

<BKProcessAssertion: 0x102c1af70; "SKProductsRequest" (finishTask:180s); id:…73BA0A71A901> [active]

}

default 14:04:34.056124 +0200 assertiond [Mxxxxxx:608] dump all assertions HWM:7 (CPUMON check): {

<BKProcessAssertion: 0x10292d6a0; "Resume" (activation:inf); id:…41AFDC851ACA> [active]

<BKProcessAssertion: 0x102c1af70; "SKProductsRequest" (finishTask:180s); id:…73BA0A71A901> [active]

}

default 14:04:34.056435 +0200 assertiond Updating PowerAssertion on Mxxxxxx:608

default 14:04:34.057760 +0200 assertiond [Mxxxxxx:608] Remove assertion: <BKProcessAssertion: 0x102a16e90; "Called by UIKit, from <redacted>" (finishTask:180s); id:…8526F7256C09>

default 14:04:34.057857 +0200 assertiond [Mxxxxxx:608] dump all assertions HWM:7 (CPUMON check): {

<BKProcessAssertion: 0x10292d6a0; "Resume" (activation:inf); id:…41AFDC851ACA> [active]

<BKProcessAssertion: 0x102c1af70; "SKProductsRequest" (finishTask:180s); id:…73BA0A71A901> [active]

}

default 14:04:34.058027 +0200 assertiond Updating PowerAssertion on Mxxxxxx:608

default 14:04:34.093240 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:0.0000 err:(null)

default 14:04:34.097485 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:0.0000 err:(null)

default 14:04:34.104801 +0200 assertiond -[BKAssertion dealloc] - <0x102d24120>

default 14:04:34.104843 +0200 cloudd [Operation 0x1060767b0] Initialized with context 0x104da9030. Background: 0, cellular: 1, QOS: 0x19

default 14:04:34.105764 +0200 cloudd [Operation 0x1060767b0] Starting operation

default 14:04:34.110621 +0200 cloudd [Operation 0x1060767b0] Operation transitioning from state 1 (cancelled=0, stop=0, error=0)

default 14:04:34.133794 +0200 assertiond -[BKAssertion dealloc] - <0x10292d5a0>

default 14:04:34.150642 +0200 cloudd [Operation 0x1060767b0] Request 0x10c102d50 set on operation

default 14:04:34.152607 +0200 cloudd [Request 0x10c102d50] Performing

default 14:04:34.152790 +0200 cloudd [Operation 0x1060767b0] Operation is now in state 2

default 14:04:34.153223 +0200 cloudd [Request 0x10c102d50] Getting URL for the user partition

default 14:04:34.153439 +0200 cloudd [Request 0x10c102d50] Getting configuration

default 14:04:34.153796 +0200 cloudd [Request 0x10c102d50] Fetching container scoped user ID

default 14:04:34.154238 +0200 cloudd [Request 0x10c102d50] Getting device ID

default 14:04:34.154525 +0200 cloudd [Request 0x10c102d50] Getting zone gates

default 14:04:34.158461 +0200 cloudd [Request 0x10c102d50] Getting push token

default 14:04:34.159195 +0200 cloudd [Request 0x10c102d50] Performing request. Background=0, cellular=1

default 14:04:34.159639 +0200 cloudd Creating a new client context 0x10c034cd0

default 14:04:34.162565 +0200 cloudd [<C2Session: 0x104e58880> addTask:<C2SessionTask: 0x104de31b0> withDescription:CKDGetRecordsURLRequest requestUUID:C4D12229-7754-430A-A456-1708F0A4A716 request:<NSMutableURLRequest: 0x1060b78f0> { URL: https://gateway.icloud.com:443/ckdatabase/api/client/record/retrieve }]

default 14:04:34.162660 +0200 cloudd created task (CKDGetRecordsURLRequest requestUUID:C4D12229-7754-430A-A456-1708F0A4A716). nsurlsessionCached (T). configurationName (host=gateway.icloud.com:outOfProcess=F:allowExpensive=T:powerNap=F:app=com.magisto.magisto).

default 14:04:34.168283 +0200 assertiond -[BKAssertion dealloc] - <0x102a16e90>

default 14:04:34.168959 +0200 cloudd TIC Enabling TLS [42:0x104f97bf0]

default 14:04:34.168999 +0200 cloudd TIC TCP Conn Start [42:0x104f97bf0]

default 14:04:34.169479 +0200 cloudd Task <6C8951DA-BFF2-487D-87EE-661E505F395C>.<5> setting up Connection 42

default 14:04:34.170988 +0200 cloudd TIC TCP Conn Connected [42:0x104f97bf0]: Err(16)

default 14:04:34.171112 +0200 cloudd TIC TCP Conn Event [42:0x104f97bf0]: 1

default 14:04:34.499242 +0200 cloudd TIC Enabling TLS [42:0x104f97bf0]

default 14:04:34.505042 +0200 cloudd TIC TLS Event [42:0x104f97bf0]: 1, Pending(0)

default 14:04:34.726035 +0200 cloudd TIC TLS Event [42:0x104f97bf0]: 2, Pending(0)

default 14:04:34.748138 +0200 cloudd TIC TLS Event [42:0x104f97bf0]: 11, Pending(0)

default 14:04:34.750128 +0200 cloudd TIC TLS Event [42:0x104f97bf0]: 12, Pending(0)

default 14:04:34.750299 +0200 cloudd TIC TLS Event [42:0x104f97bf0]: 14, Pending(0)

default 14:04:34.783400 +0200 CommCenter QMI: Svc=0x01(WDS) Req MsgId=0x555b Bin=[<private>]

default 14:04:34.805138 +0200 CommCenter QMI: Svc=0x01(WDS) Resp MsgId=0x555b Bin=[<private>]

default 14:04:34.821838 +0200 trustd ocsp responder: (null) did not include status of requested cert

default 14:04:34.840003 +0200 trustd cert[0]: AnchorApple =(path)[]> 0

default 14:04:34.853031 +0200 trustd cert[0]: AnchorApple =(path)[]> 0

default 14:04:34.853400 +0200 trustd cert[0]: CheckIntermediateMarkerOid =(path)[]> 0

default 14:04:34.856745 +0200 cloudd TIC TLS Trust Result [42:0x104f97bf0]: 0

default 14:04:35.083158 +0200 cloudd TIC TLS Event [42:0x104f97bf0]: 20, Pending(0)

default 14:04:35.083872 +0200 cloudd TIC TCP Conn Event [42:0x104f97bf0]: 8

default 14:04:35.084029 +0200 cloudd TIC TLS Handshake Complete [42:0x104f97bf0]

default 14:04:35.087604 +0200 cloudd [Request 0x10c102d50] requestForEstablishedConnection

default 14:04:35.091504 +0200 cloudd NSURLSessionLocalTaskAuthenticator - getAuthenticationHeadersForTask

default 14:04:35.112266 +0200 cloudd Task <6C8951DA-BFF2-487D-87EE-661E505F395C>.<5> now using Connection 42

default 14:04:35.113203 +0200 cloudd Task <6C8951DA-BFF2-487D-87EE-661E505F395C>.<5> sent request, body S

default 14:04:35.383109 +0200 CommCenter QMI: Svc=0xe2(BSP) Ind MsgId=0xe021 Bin=[<private>]

default 14:04:35.385623 +0200 CommCenter QMI: Svc=0x03(NAS) Ind MsgId=0x0051 Bin=['01 34 00 80 03 04 04 30 09 51 00 28 00 14 06 00 C4 F8 A9 FF 1E 01 A2 01 00 64 A4 18 00 02 64 00 00 00 00 00 00 00 00 00 00 FF 00 00 00 F3 00 00 00 A9 FF FF FF']

default 14:04:35.420757 +0200 cloudd Task <6C8951DA-BFF2-487D-87EE-661E505F395C>.<5> received response, status 200 content U

default 14:04:35.421685 +0200 cloudd Task <6C8951DA-BFF2-487D-87EE-661E505F395C>.<5> response ended

default 14:04:35.423056 +0200 cloudd [Request 0x10c102d50] URLSession:dataTask:didReceiveResponse:completionHandler:

default 14:04:35.425327 +0200 cloudd [Request 0x10c102d50] URLSession:dataTask:didReceiveData:

default 14:04:35.428169 +0200 cloudd captureMetricsForTask=CKDGetRecordsURLRequest requestUUID:C4D12229-7754-430A-A456-1708F0A4A716:host=gateway.icloud.com:remoteAddress=<private>:localAddress=<private>:connectionUUID=9BD33CB7-5326-4368-A64F-1883AFEA6079:qualityOfService=userInitiated:reuse=0:i=en0:protocol=h2:requestHeaderBytes=1009:requestBodyBytes=485:responseHeaderBytes=386:responseBodyBytes=1011:err=F:dnsDuration=0.000:tcpStartDelay=0.441:tcpDuration=0.588:sslStartDelay=0.006:sslDuration=0.611:requestStartDelay=0.029:requestDuration=0.000:responseStartDelay=0.307:responseDuration=0.000:transactionDuration=0.307:outOfProcess=F:allowExpensive=T:powerNap=F:app=com.magisto.magisto:2app=:disc=F:pool=com.apple.cloudkit.BackgroundConnectionPool:tlsPinning=T:reqTimeout=60.00:resTimeout=-1.00:appleIdSessionId=com.apple.cloudkit:metricRequest=F

default 14:04:35.428846 +0200 cloudd [<private> removeTask:<private>] - withDescription:<private>

default 14:04:35.433139 +0200 cloudd [Operation 0x1060b6e10] Initialized with context 0x104da9030. Background: 0, cellular: 1, QOS: 0x19

default 14:04:35.434175 +0200 cloudd [Operation 0x1060b6e10] Starting operation

default 14:04:35.434287 +0200 cloudd [Request 0x10c102d50] URLSession:task:didCompleteWithError:

default 14:04:35.436147 +0200 cloudd [Request 0x10c102d50] Finishing request with no error

default 14:04:35.439303 +0200 cloudd [Operation 0x1060767b0] Request 0x0 set on operation

default 14:04:35.440887 +0200 cloudd [Operation 0x10a774870] Initialized with context 0x104da9030. Background: 0, cellular: 1, QOS: 0x19

default 14:04:35.442135 +0200 cloudd [Operation 0x10a774870] Starting operation

default 14:04:35.447764 +0200 cloudd [Operation 0x10a774870] Operation transitioning from state 1 (cancelled=0, stop=0, error=0)

default 14:04:35.448813 +0200 cloudd [Operation 0x10a774870] Operation is now in state 2

default 14:04:35.452323 +0200 cloudd [Operation 0x10a774870] Operation transitioning from state 2 (cancelled=0, stop=0, error=0)

default 14:04:35.452988 +0200 cloudd [Operation 0x10a774870] Operation is now in state 4

default 14:04:35.453350 +0200 cloudd [Operation 0x10a774870] Operation transitioning from state 4 (cancelled=0, stop=0, error=0)

default 14:04:35.454020 +0200 cloudd [Operation 0x10a774870] Operation is now in state 5

default 14:04:35.454241 +0200 cloudd [Operation 0x10a774870] Operation transitioning from state 5 (cancelled=0, stop=0, error=0)

default 14:04:35.454690 +0200 cloudd [Operation 0x10a774870] Operation is now in state 6

default 14:04:35.488775 +0200 cloudd [Operation 0x10a774870] Operation transitioning from state 6 (cancelled=0, stop=0, error=0)

default 14:04:35.489730 +0200 cloudd [Operation 0x10a774870] Operation is now in state 4294967295

default 14:04:35.512852 +0200 cloudd [Operation 0x1060767b0] Operation transitioning from state 2 (cancelled=0, stop=0, error=0)

default 14:04:35.514740 +0200 cloudd [Operation 0x10a756440] Initialized with context 0x104da9030. Background: 0, cellular: 1, QOS: 0x19

default 14:04:35.515997 +0200 cloudd [Operation 0x1060767b0] Operation is now in state 4

default 14:04:35.516556 +0200 cloudd [Operation 0x10a756440] Starting operation

default 14:04:35.526856 +0200 cloudd [Operation 0x10a756440] Operation transitioning from state 1 (cancelled=0, stop=0, error=0)

default 14:04:35.528966 +0200 cloudd [Operation 0x10a756440] Operation is now in state 2

default 14:04:35.529585 +0200 cloudd [Operation 0x10a756440] Operation transitioning from state 2 (cancelled=0, stop=0, error=0)

default 14:04:35.531960 +0200 cloudd [Operation 0x10a756440] Operation is now in state 3

default 14:04:35.559461 +0200 cloudd #ae13384d ACSMightCurrentNetworkHaveCachingServer(options={

capabilities = {

import = 1;

namespaces = 1;

personalCaching = 1;

};

quickMiss = 1;

"x-apple-persistent-identifier" = 2e04;

}, callbackQueue=0x0, callback=0x16b76d798)

default 14:04:35.565516 +0200 cloudd #ae13384d ACSMightCurrentNetworkHaveCachingServer -> [new] mightHave NO, error (null), elapsed 0.006

default 14:04:35.565831 +0200 cloudd file content validation enabled by default for dataclass com.apple.Dataclass.CloudKit with container com.apple.photos.cloud. Does not impact chunk validation.

default 14:04:35.568032 +0200 cloudd HttpURL (https://gateway.icloud.com:443/content/11593352801/authorizeGet)

default 14:04:35.568862 +0200 cloudd RequestHeader (x-apple-request-uuid:0F087804-D5E5-4171-B716-9093A1101504)

default 14:04:35.572350 +0200 cloudd [<C2Session: 0x104e58880> addTask:<C2SessionTask: 0x10d7da9c0> withDescription:authorizeGetForFiles requestUUID:0F087804-D5E5-4171-B716-9093A1101504 request:<NSMutableURLRequest: 0x10c0381a0> { URL: https://gateway.icloud.com:443/content/11593352801/authorizeGet }]

default 14:04:35.572525 +0200 cloudd created task (authorizeGetForFiles requestUUID:0F087804-D5E5-4171-B716-9093A1101504). nsurlsessionCached (T). configurationName (host=gateway.icloud.com:outOfProcess=F:allowExpensive=T:powerNap=F:app=com.magisto.magisto).

default 14:04:35.575740 +0200 cloudd Task <DF96B2D6-C9A3-4EB5-9F70-F6B4D87490EB>.<6> now using Connection 42

default 14:04:35.576039 +0200 cloudd Task <DF96B2D6-C9A3-4EB5-9F70-F6B4D87490EB>.<6> sent request, body S

default 14:04:35.945702 +0200 cloudd Task <DF96B2D6-C9A3-4EB5-9F70-F6B4D87490EB>.<6> received response, status 200 content K

default 14:04:35.946526 +0200 cloudd Task <DF96B2D6-C9A3-4EB5-9F70-F6B4D87490EB>.<6> response ended

default 14:04:35.949351 +0200 cloudd HttpStatus (HTTP/1.1 200 no error)

default 14:04:35.949582 +0200 cloudd ResponseHeader (Server:AppleHttpServer/2f080fc0)

default 14:04:35.950028 +0200 cloudd ResponseHeader (x-apple-request-uuid:0F087804-D5E5-4171-B716-9093A1101504)

default 14:04:35.950150 +0200 cloudd ResponseHeader (Via:xrail:st13p00ic-zteu25234101:8301:17E107:grp62, icloudedge:se03p01ic-zteu011118:7401:18RC19:Seattle)

default 14:04:35.950730 +0200 cloudd ResponseHeader (x-responding-instance:content.15900401.st42p59ic-tyfb03210701:8001.1804B55)

default 14:04:35.953887 +0200 cloudd captureMetricsForTask=authorizeGetForFiles requestUUID:0F087804-D5E5-4171-B716-9093A1101504:host=gateway.icloud.com:remoteAddress=<private>:localAddress=<private>:connectionUUID=9BD33CB7-5326-4368-A64F-1883AFEA6079:qualityOfService=userInitiated:reuse=1:i=en0:protocol=h2:requestHeaderBytes=723:requestBodyBytes=93:responseHeaderBytes=416:responseBodyBytes=730:err=F:dnsDuration=0.000:tcpStartDelay=0.000:tcpDuration=0.000:sslStartDelay=-1.000:sslDuration=-1.000:requestStartDelay=0.001:requestDuration=0.000:responseStartDelay=0.369:responseDuration=0.000:transactionDuration=0.369:outOfProcess=F:allowExpensive=T:powerNap=F:app=com.magisto.magisto:2app=:disc=F:pool=:tlsPinning=T:reqTimeout=600.00:resTimeout=3600.00:appleIdSessionId=:metricRequest=F

default 14:04:35.954646 +0200 cloudd [<private> removeTask:<private>] - withDescription:<private>

default 14:04:35.954751 +0200 cloudd client.trigger:#N Random sample for 0x350000 is skip

default 14:04:35.955728 +0200 cloudd Observed 0.0202 Mbps over 0.3878 seconds for 978 bytes. 0.0071 seconds in queue.

default 14:04:35.958557 +0200 cloudd PutComplete at Edge Protocol : Disabled

default 14:04:35.960930 +0200 analyticsd [<private>] no observers; dropped.

default 14:04:35.967278 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:0.0000 err:(null)

error 14:04:36.027279 +0200 cloudd Unregistering item without an asset handle for itemID=393

default 14:04:36.028878 +0200 cloudd getItemReaderWriterForItemCallback did not succeed

default 14:04:36.072217 +0200 cloudd itemId:395 local fulfillment took 0.1055 seconds for 9106292 bytes. Validated for Resume (0 bytes), Resumed (0 bytes), Fullfilled Locally (9106292 bytes)

default 14:04:36.110924 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:0.9901 err:(null)

default 14:04:36.163213 +0200 cloudd Renaming <private> to <private> for item 395

default 14:04:36.164801 +0200 cloudd itemId 395 completed

default 14:04:36.174329 +0200 cloudd client.trigger:#N Random sample for 0x200002 is skip

default 14:04:36.183475 +0200 analyticsd [<private>] no observers; dropped.

default 14:04:36.187145 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:0.9901 err:(null)

default 14:04:36.188364 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:1.0000 err:(null)

default 14:04:36.192219 +0200 assetsd downloadDidFinishForResourceDownloadTask: <private>, with error: (null)

default 14:04:36.192979 +0200 cloudd [Operation 0x10a756440] Operation transitioning from state 3 (cancelled=0, stop=0, error=0)

default 14:04:36.194864 +0200 cloudd [Operation 0x10a756440] Operation is now in state 4294967295

default 14:04:36.199771 +0200 cloudd [Operation 0x1060767b0] Operation transitioning from state 4 (cancelled=0, stop=0, error=0)

default 14:04:36.200390 +0200 cloudd [Operation 0x1060767b0] Operation is now in state 4294967295

default 14:04:36.225757 +0200 Mxxxxxx -[iCloudDownloadItem download:progress:]_block_invoke video, progress:1.0000 err:(null)

default 14:04:36.242869 +0200 Mxxxxxx ***************** requestAVAssetForVideo END *****************

default 14:04:36.243075 +0200 Mxxxxxx *** Assertion failure in -[PHAsset getAVAssetForVideoAllowNetwork:progress:comp:], /Users/amir/magisto-iOS/Development/Classes/PHAsset+Additions.m:200

default 14:04:36.260405 +0200 Mxxxxxx *** Terminating app due to uncaught exception 'NSInternalInconsistencyException', reason: 'asset is missing'

0
miamitwinz OP
Mar ’21
Were you able to resolve this issue?
0
requestAVAssetForVideo returns AVAsset==nil while networkAccessAllowed=true
First post date Last post date
 
 
Q