The short version is Plex camera upload crashes on upload of very long video files.
The longer version is Apple has a bug that caused videos longer than some magic amount (30-45 minute range) to be invisible to the normal file transfer process via USB (at least on Windows). Those files also cause the camera upload (backup) to crash. It will download info from iCloud, start to upload them almost instantly change to essentially waiting to upload status. I am running Plex server version 1.3.4.3285
If you care to get some diagnostic logs, I will get it referred to the plex for iOS development team
Make sure you are running Plex for iOS version 4.7 (current version)
See this support page for instructions of how to get the zipped app logs emailed to yourself so that you can attach here
Please give details of time of test / crash
Ok, I have the diagnostic logs and a video of the screen while the issue occurred. Since it appears that the logs contain some slightly private information is there a way I can PM them in instead of publicly posting them?
if not easy to redact the private information, you can send by Private Message to me
Thanks @antgiant for sending the Plex for iOS log. The log does not show any crash of the app but indicates an error when attempting to upload to the server.
2017/02/09 20:38:38.963 (72 MB) (837870) I PMKCameraUploadEngine.m:1680 | Created data transfer task to upload IMG_6741.MOV
2017/02/09 20:38:38.963 (72 MB) (837870) I PMKCameraUploadEngine.m:2009 | Ending background task.
2017/02/09 20:38:39.011 (72 MB) (837870) I PMKCameraUploadEngine.m:1224 | Beginning background task.
2017/02/09 20:38:39.015 (72 MB) (837870) I PMKCameraUploadEngine.m:2485 | Something went wrong. Starting process over.
2017/02/09 20:38:39.016 (72 MB) (838223) I PMKCameraUploadEngine.m:1771 | Ending upload.
2017/02/09 20:38:39.016 (72 MB) (838223) I PMKCameraUploadEngine.m:1797 | In the middle of the upload process, attempting to finish up.
2017/02/09 20:38:39.016 (72 MB) (838223) I PMKCameraUploadEngine.m:1801 | No more tasks, all done.
This does mean we need to see the logs from both ends - ie the Plex for iOS app log and the corresponding Plex Media Server.log
So please ensure logging is enabled on the Plex Media Server as well. (In Plex Web App, select Settings / Server / General / Show Advanced). Ensure Debug Logging is enabled. For this test also please enable verbose logging option which is on same settings page. Save changes.
Restart the server to get fresh logs
Repeat the test
When the error occurs, take screenshots as before - and get both the server and iOS logs
See https://support.plex.tv/hc/en-us/articles/200250417-Plex-Media-Server-Log-Files
After you get the diagnostics, disable verbose logging on the server. You can leave Debug logging enabled which is the default
Thanks. I actually already had debug logging on but by the time I grabbed the logs this morning there had been enough activity to cycle this issue out of all six Media Server logs. I’ll grab all three as soon as I can get access to the problematic phone again. Thanks again for your quick help.
@antgiant said:
Thanks. I actually already had debug logging on but by the time I grabbed the logs this morning there had been enough activity to cycle this issue out of all six Media Server logs. I’ll grab all three as soon as I can get access to the problematic phone again. Thanks again for your quick help.
Try to do a controlled test with no activity.
Sorry it took me a while to be able to repeat this. Here are the verbose logs.
Phone
2017/02/18 21:31:28.709 (96 MB) (2973771) I PMKCameraUploadEngine.m:1877 | Asset IMG_6741.MOV is downloading data (100%). 2017/02/18 21:31:28.896 (96 MB) (2973771) I PMKAssetController.m:279 | Video export progress: 0.993535 2017/02/18 21:31:28.997 (96 MB) (2973771) I PMKAssetController.m:279 | Video export progress: 0.9945368 2017/02/18 21:31:29.098 (96 MB) (2973771) I PMKAssetController.m:279 | Video export progress: 0.9955464 2017/02/18 21:31:29.196 (96 MB) (2973771) I PMKAssetController.m:279 | Video export progress: 0.9965483 2017/02/18 21:31:29.312 (96 MB) (2973771) I PMKAssetController.m:279 | Video export progress: 0.997721 2017/02/18 21:31:29.511 (96 MB) (2973771) I PMKAssetController.m:279 | Video export progress: 0.9997247 2017/02/18 21:31:30.170 (96 MB) (2973820) I PMKAssetController.m:304 | Video export completed successfully. 2017/02/18 21:31:30.205 (96 MB) (2973822) I PMKCameraUploadEngine.m:1675 | Created data transfer task to check partial upload for IMG_6741.MOV 2017/02/18 21:31:30.205 (96 MB) (2973822) I PMKCameraUploadEngine.m:2009 | Ending background task. 2017/02/18 21:31:30.331 (96 MB) (2973771) D PMKDataTransferManager.m:1159 | Handling background URL session events in <PMKDataTransferManager:0x174157760 name=CameraUpload> (1 tasks) 2017/02/18 21:31:30.396 (96 MB) (2973771) D PMKDataTransferManager.m:445 | Finished handling background URL session events in <PMKDataTransferManager:0x174157760 name=CameraUpload> 2017/02/18 21:31:30.964 (96 MB) (2973771) D PMKDataTransferManager.m:1159 | Handling background URL session events in <PMKDataTransferManager:0x174157760 name=CameraUpload> (1 tasks) 2017/02/18 21:31:31.010 (96 MB) (2973771) D PMKDataTransferManager.m:445 | Finished handling background URL session events in <PMKDataTransferManager:0x174157760 name=CameraUpload> 2017/02/18 21:31:31.017 (96 MB) (2974697) I PMKCameraUploadEngine.m:1224 | Beginning background task. 2017/02/18 21:31:31.020 (96 MB) (2974697) I PMKCameraUploadEngine.m:2038 | Starting background timer with time: 39.92187087499769 2017/02/18 21:31:31.020 (96 MB) (2974697) I PMKCameraUploadEngine.m:2436 | Neither asset nor partial upload were found. Uploading from beginning. 2017/02/18 21:31:31.188 (96 MB) (2974475) I PMKCameraUploadEngine.m:1680 | Created data transfer task to upload IMG_6741.MOV 2017/02/18 21:31:31.188 (96 MB) (2974475) I PMKCameraUploadEngine.m:2009 | Ending background task. 2017/02/18 21:35:31.011 (96 MB) (2973771) D PMKDataTransferManager.m:1159 | Handling background URL session events in <PMKDataTransferManager:0x174157760 name=CameraUpload> (1 tasks) 2017/02/18 21:35:31.034 (96 MB) (2975578) D PMKNetworkTask.m:192 | SERVER (1ecfa8366c0e30e4c9351c98d3e42ae07e0a9c1c): GET /:/timeline?bufferedTime=0&duration=1922153&key=%2Flibrary%2Fmetadata%2F674&location=lan&playQueueItemID=775244&ratingKey=674&state=paused&time=0&X-Plex-Device-Name=XXXXXXXXXX 2017/02/18 21:35:31.096 (96 MB) (2973771) D PMKDataTransferManager.m:445 | Finished handling background URL session events in <PMKDataTransferManager:0x174157760 name=CameraUpload> 2017/02/18 21:35:53.317 (96 MB) (2973771) D PMKDataTransferManager.m:1159 | Handling background URL session events in <PMKDataTransferManager:0x174157760 name=CameraUpload> (1 tasks) 2017/02/18 21:35:53.365 (96 MB) (2975656) I PMKCameraUploadEngine.m:1224 | Beginning background task. 2017/02/18 21:35:53.369 (96 MB) (2975656) I PMKCameraUploadEngine.m:2038 | Starting background timer with time: 29.92760083335452 2017/02/18 21:35:53.369 (96 MB) (2975656) I PMKCameraUploadEngine.m:2485 | Something went wrong. Starting process over. 2017/02/18 21:35:53.369 (96 MB) (2975656) I PMKCameraUploadEngine.m:1771 | Ending upload. 2017/02/18 21:35:53.370 (96 MB) (2975656) I PMKCameraUploadEngine.m:1797 | In the middle of the upload process, attempting to finish up. 2017/02/18 21:35:53.370 (96 MB) (2975656) I PMKCameraUploadEngine.m:1801 | No more tasks, all done. 2017/02/18 21:35:53.370 (96 MB) (2975656) I PMKCameraUploadEngine.m:1832 | Upload ended.
Server
Feb 18, 2017 21:47:24.529 [1064] DEBUG - Request: [192.168.1.YYY:53969 (Subnet)] POST /library/metadata?createdAt=1484404429&filename=IMG_6741.MOV&locationID=10§ionID=5&subdirectory=XXXXXXXXXX&type=12 (6 live) TLS GZIP Signed-in Token (antgiant) Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * Host => 192.168.1.XXX:32400 Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * User-Agent => PlexMobile/4.7 (iPhone; iOS 10.2.1; Scale/3.00) Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Device-Screen-Density => 3 Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Supported-Commands => abort,changeQuality Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Device => iPhone Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Platform => iOS Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Sync-Version => 2 Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Token => xxxxxxxxxxxxxxxxxxxx Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Username => antgiant Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Provides => client,controller,sync-target,player,pubsub-player Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Version => 4.7 Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Model => 8,2 Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * Content-Length => 0 Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Product => Plex for iOS Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * Connection => keep-alive Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Client-Identifier => 8A68175F-F1A7-4D06-B178-ED147687840D Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * Accept-Language => en-US;q=1 Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Device-Screen-Resolution => 1242x2208 Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Device-Vendor => Apple Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Platform-Version => 10.2.1 Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * Accept => text/xml,application/xml Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * Content-Type => application/octet-stream Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * Accept-Encoding => gzip, deflate Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Http-Pipeline => infinite Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * Content-Range => bytes */5767835492 Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * X-Plex-Device-Name => XXXXXXXXXX Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * createdAt => 1484404429 Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * filename => IMG_6741.MOV Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * locationID => 10 Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * sectionID => 5 Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * subdirectory => XXXXXXXXXX Feb 18, 2017 21:47:24.529 [1064] VERBOSE - * type => 12 Feb 18, 2017 21:47:24.900 [1064] WARN - SLOW QUERY: It took 375.000000 ms to retrieve 0 items. Feb 18, 2017 21:47:24.900 [8776] DEBUG - Completed: [192.168.1.YYY:53969] 404 POST /library/metadata?createdAt=1484404429&filename=IMG_6741.MOV&locationID=10§ionID=5&subdirectory=XXXXXXXXXX&type=12 (6 live) TLS GZIP 381ms 379 bytes Feb 18, 2017 21:47:25.064 [8776] DEBUG - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authentication. Feb 18, 2017 21:47:25.064 [8776] DEBUG - Auth: authenticated user 1 as antgiant Feb 18, 2017 21:47:25.064 [8776] DEBUG - Auth: Came in with a super-token, authorization succeeded. Feb 18, 2017 21:47:25.064 [8776] ERROR - Exception parsing request: bad lexical cast: source type value could not be interpreted as target Feb 18, 2017 21:47:25.064 [8776] DEBUG - Request: [192.168.1.YYY:53969 (Subnet)] POST /library/metadata?createdAt=1484404429&filename=IMG_6741.MOV&locationID=10§ionID=5&subdirectory=XXXXXXXXXX&type=12 (6 live) TLS GZIP Signed-in Token (antgiant) Feb 18, 2017 21:47:25.064 [8776] VERBOSE - * Host => 192.168.1.XXX:32400 Feb 18, 2017 21:47:25.064 [8776] VERBOSE - * User-Agent => PlexMobile/4.7 (iPhone; iOS 10.2.1; Scale/3.00) Feb 18, 2017 21:47:25.064 [8776] VERBOSE - * X-Plex-Device-Screen-Density => 3 Feb 18, 2017 21:47:25.064 [8776] VERBOSE - * X-Plex-Supported-Commands => abort,changeQuality Feb 18, 2017 21:47:25.064 [8776] VERBOSE - * X-Plex-Device => iPhone Feb 18, 2017 21:47:25.064 [8776] VERBOSE - * X-Plex-Platform => iOS Feb 18, 2017 21:47:25.064 [8776] VERBOSE - * X-Plex-Sync-Version => 2 Feb 18, 2017 21:47:25.064 [8776] VERBOSE - * X-Plex-Token => xxxxxxxxxxxxxxxxxxxx Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * X-Plex-Username => antgiant Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * X-Plex-Provides => client,controller,sync-target,player,pubsub-player Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * X-Plex-Version => 4.7 Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * X-Plex-Model => 8,2 Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * Content-Length => 5767835492 Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * X-Plex-Product => Plex for iOS Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * Connection => keep-alive Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * X-Plex-Client-Identifier => 8A68175F-F1A7-4D06-B178-ED147687840D Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * Accept-Language => en-US;q=1 Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * X-Plex-Device-Screen-Resolution => 1242x2208 Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * X-Plex-Device-Vendor => Apple Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * X-Plex-Platform-Version => 10.2.1 Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * Accept => text/xml,application/xml Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * Content-Type => application/octet-stream Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * Accept-Encoding => gzip, deflate Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * X-Plex-Http-Pipeline => infinite Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * X-Plex-Device-Name => XXXXXXXXXX Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * createdAt => 1484404429 Feb 18, 2017 21:47:25.065 [8776] VERBOSE - * filename => IMG_6741.MOV Feb 18, 2017 21:47:25.066 [8776] VERBOSE - * locationID => 10 Feb 18, 2017 21:47:25.066 [8776] VERBOSE - * sectionID => 5 Feb 18, 2017 21:47:25.066 [8776] VERBOSE - * subdirectory => XXXXXXXXXX Feb 18, 2017 21:47:25.066 [8776] VERBOSE - * type => 12 Feb 18, 2017 21:47:25.067 [8780] DEBUG - Completed: [192.168.1.YYY:53969] 500 POST /library/metadata?createdAt=1484404429&filename=IMG_6741.MOV&locationID=10§ionID=5&subdirectory=XXXXXXXXXX&type=12 (6 live) TLS GZIP 1ms 357 bytes (pipelined: 2) Feb 18, 2017 21:47:25.068 [8780] DEBUG - Request: [192.168.1.YYY:53969 (WAN)] (6 live) TLS Signed-in Feb 18, 2017 21:47:25.068 [8780] ERROR - Error parsing HTTP request: Feb 18, 2017 21:47:25.068 [8776] DEBUG - Completed: [192.168.1.YYY:53969] 400 (6 live) TLS 0ms 246 bytes (pipelined: 3) Feb 18, 2017 21:47:25.068 [8780] DEBUG - Request: [192.168.1.YYY:53969 (WAN)] (6 live) TLS Signed-in Feb 18, 2017 21:47:25.068 [8780] ERROR - Error parsing HTTP request: ݔV鐍 Feb 18, 2017 21:47:25.068 [8776] DEBUG - Completed: [192.168.1.YYY:53969] 400 (6 live) TLS 0ms 246 bytes (pipelined: 4) Feb 18, 2017 21:47:25.068 [8780] DEBUG - Request: [192.168.1.YYY:53969 (WAN)] (6 live) TLS Signed-in Feb 18, 2017 21:47:25.068 [8780] ERROR - Error parsing HTTP request: e��ǂ햍 *࠲G:
Hmm, it appears that the binary corrupts forum posts here. I’ll attach the files here in case you need the binary.
@antgiant said:
Hmm, it appears that the binary corrupts forum posts here. I’ll attach the files here in case you need the binary.
Without full log files I cannot even establish which version of Plex Media Server is being used for this camera upload
There was an issue like this arising if the destination album has not been created in advance but a fix was released
There is a failure processing a parameter. It could be the specified subdirectory
Feb 18, 2017 21:47:25.064 [8776] ERROR - Exception parsing request: bad lexical cast: source type value could not be interpreted as target
and the request being
Feb 18, 2017 21:47:24.529 [1064] DEBUG - Request: [192.168.1.YYY:53969 (Subnet)] POST /library/metadata?createdAt=1484404429&filename=IMG_6741.MOV&locationID=10§ionID=5&subdirectory=XXXXXXXXXX&type=12 (6 live) TLS GZIP Signed-in Token (antgiant)
You can send me the log by private message. It is possible that there is a bug in the fix that was supposed to create the subdirectory. Need to see the full request. Also could you send me the directory structure for the uploads library
@antgiant need to see the exact syntax of that request that is arriving at the server
POST /library/metadata?createdAt=1484404429&filename=IMG_6741.MOV&locationID=10§ionID=5&subdirectory=XXXXXXXXXX&type=12
Could you make sure verbose logging is set at both ends - plex for ios and plex media server (as you have currently Debug+Verbose enabled)
Are you familiar with wireshark (https://www.wireshark.org/#download) ? If you run it on the server machine and that start an upload that errors in this way then capturing all traffic and filtering for the ip address of the iOS device and saving the pcap file would allow me to see the full request - you could send all this by private message
I have just PMd you the full untouched log dumps from the phone and from the server. Verbose was turned on for both. If I get a chance I will set up wireshark tonight and send you those logs as well. However, I strongly suspect this is some kind of overflow error. The phone in question had over 1,000 items of which 2 were extremely large. All of the 1,000+ items except the two extremely large files backed up successfully with this configuration. In fact part of the delay in me posting again was waiting for 200 or 300 more items to finish successfully backing up before Plex got back around to trying one of the large files.
Thanks for the logs. I need to see the definiton of the libraries.
The XML from this request
http://xxx.xxx.xxx.xxx:32400/library/sections/all?X-Plex-Token=xxxxxxxxxxxxxxxxxxxxxxxxxx
where xxx.xxx.xxx.xxx is the local IP address of the server and xxxxxxxxxxxxxxxxxxx is the access token for the server used by plex web - which you can find from viewing the media info for an item in the library in the plex web client and then selecting View XML - the token will be in the url
Sorry just made it back to a computer. PMd you this working on Wireshark now.
@antgiant - thank you with all your help with the diagnostics. This has now been raised with the development teams
The issue is with the video uploads
@sa2000 Glad to help. Overly large files breaking things?
