Plex Server | Local Movies/TV shares do not respond

Unexpected. Caught both the Synology as well as the QNAP support sec=sys with NFS.

sh-5.0# mount  -t nfs -o defaults,sec=sys  192.168.0.21:/movies /mnt
sh-5.0# mount | grep mnt
192.168.0.23:/volume1/Name with spaces on /mnt type nfs4 (rw,relatime,vers=4.1,rsize=131072,wsize=131072,namlen=255,hard,proto=tcp,timeo=600,retrans=2,sec=sys,clientaddr=192.168.0.194,local_lock=none,addr=192.168.0.23)
vienna:/movies on /mnt type nfs4 (rw,relatime,vers=4.2,rsize=1048576,wsize=1048576,namlen=255,hard,proto=tcp,timeo=15,retrans=2,sec=sys,clientaddr=192.168.0.194,local_lock=none,addr=192.168.0.21)
sh-5.0# 

Checking Ubuntu 18.04 now

I know NFS v3 also supports it but call out vers=4 as another mount option.

Supplemental:

start with options, one at a time, like I show above in my screenshots, in a mount-umount-add an option-try again until you find the one it doesn’t like.

:/mnt$ sudo mount -t nfs -o defaults,sec=sys 192.168.10.2:/nfs/TV /mnt/tv
[sudo] password for USER:
USER@htpc:/mnt$ ls -l
total 8
drwxrwx---+ 23 root USER 4096 Jan  2 06:08 tv
USER@htpc:/mnt$ cd tv
-bash: cd: tv: Permission denied
USER@htpc:/mnt$ su
Password:
su: Authentication failure
USER@htpc:/mnt$ sudo su
root@htpc:/mnt# cd tv
root@htpc:/mnt/tv# ls -l
total 96
drwxrwsrwx  2    999 USER  4096 Dec  7  2013 'Baby Einstein'
drwxrwxrwx  4 root   root   4096 Dec 28 07:40 'Doug(1996)'

Looks like it worked

Further tested

USER@htpc:/mnt$ sudo mount -t nfs -o defaults,sec=sys,auto,rw,rsize=262144,wsize=262144,hard,intr,bg,nofail 192.168.10.2:/nfs/TV /mnt/tv
USER@htpc:/mnt$ ls -l
total 8
drwxrwx---+ 23 root USER 4096 Jan  2 06:08 tv
USER@htpc:/mnt$ cd /tv
-bash: cd: /tv: No such file or directory
USER@htpc:/mnt$ cd tv
-bash: cd: tv: Permission denied
USER@htpc:/mnt$ sudo cd tv
sudo: cd: command not found
USER@htpc:/mnt$ sudo su
root@htpc:/mnt# cd tv
root@htpc:/mnt/tv# ls -l
total 96
drwxrwsrwx  2    999 USER  4096 Dec  7  2013 'Baby Einstein'
drwxrwxrwx  4 root   root   4096 Dec 28 07:40 'Doug(1996)'
drwxrwxr-x 33 nobody USER  4096 Nov  1  2017 'Family Guy'

the ending 0 0 did not take. So for the test should I temporarily disable the CIF mount and instead use nfs and see if the PMS stabilizes?

there is an issue of root access to the share. Still not able to access unless I am ‘ROOT’. Which will impact PMS accessing the media.

Is the error I see on my Roku.

That’s telling me the Roku doesn’t see the server at all.
Did restarting the Roku result in no improvement?

Restarting PMS service on the Ubuntu server restored everything. During the issue files on the NAS are still accessible.

Same error on iPad.

I dont think this has to do with NAS/filesystem, I just had to restart the server process again and can confirm no one was using plex today.

Would it be possible to review the logs and if so can we capture more data?

Yes, please. Seeing your results is obvious I need to review them.

Stop PMS.
Create a tar.gz (tar ball) of the Logs directory and attach it.

Ok will do right now, it just stopped again and I am streaming two shows. One from a laptop web and the other from iPad.

pms-logs2.tar.gz (3.6 MB)

attached are the latest logs.

I’m seeing where the iPad is responding. It seems to start and stop. Is that you stopping it?

Feb 08, 2020 04:59:19.379 [0x7f1d90bd7700] DEBUG - Request: [127.0.0.1:42804 (WAN)] GET /:/timeline?bufferedTime=54&duration=1396672&key=%2Flibrary%2Fmetadata%2F3559&playQueueItemID=9749&playbackTime=48843&ratingKey=3559&state=buffering&time=95034 (8 live) TLS GZIP Signed-in Token (nuffsaid21)
Feb 08, 2020 04:59:19.379 [0x7f1d73fff700] DEBUG - Cleaning directory for session F3B6159B-BF8B-4D8D-B82E-835A70C2D333 (/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-F3B6159B-BF8B-4D8D-B82E-835A70C2D333-ef9ae763-190c-49a1-b80c-ac881eba75f2)
Feb 08, 2020 04:59:19.379 [0x7f1d90bd7700] DEBUG - Client [E2D8ED00-301D-4930-AAB5-1565FE6811E3] reporting timeline state buffering, progress of 95034/1396672ms for guid=, ratingKey=3559 url=, key=/library/metadata/3559, containerKey=, metadataId=3559, source=
Feb 08, 2020 04:59:19.380 [0x7f1d90bd7700] DEBUG - Play progress on 3559 'The One Where No One Proposes' - got played 95034 ms by account 1!
Feb 08, 2020 04:59:19.381 [0x7f1d90bd7700] DEBUG - [Now] User is nuffsaid21 (ID: 1)
Feb 08, 2020 04:59:19.381 [0x7f1d90bd7700] DEBUG - [Now] Device is iOS (Hamam’s iPad).
Feb 08, 2020 04:59:19.383 [0x7f1db4f57b80] DEBUG - Transcoder: Cleaning old transcode directories.
Feb 08, 2020 04:59:19.383 [0x7f1db4f57b80] DEBUG - Transcoder: Cleaning old transcode directory: "/var/lib/plexmediaserver/Library/Application Support/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-F3B6159B-BF8B-4D8D-B82E-835A70C2D333-ef9ae763-190c-49a1-b80c-ac881eba75f2"

I also see Chrome accessing it to play.

Yes I did restart it, wife said it wasn’t working.

OK. I’ll go back further and see if I can find anything.

Thanks and let me know if anything else needs to be captured or enabled to aid in troubleshooting.

DEBUG logging is all I need. VERBOSE would be too much.

This is future time for me. Which timezone are you in please?

bufferedTime=156&duration=1318336&key=%2Flibrary%2Fmetadata%2F3442&location=lan&playQueueItemID=9748&playbackTime=578367&ratingKey=3442&state=playing&time=636634 (53 live) TLS GZIP Signed-in Token (nuffsaid21)
Feb 08, 2020 04:38:42.908 [0x7fa00f7d6700] DEBUG - Client [E2D8ED00-301D-4930-AAB5-1565FE6811E3] reporting timeline state playing, progress of 636634/1318336ms for guid=, ratingKey=3442 url=, key=/library/metadata/3442, containerKey=, metadataId=3442, source=
Feb 08, 2020 04:38:42.910 [0x7fa00f7d6700] DEBUG - Play progress on 3442 'The One Where Rachel Has A Baby (2)' - got played 636634 ms by account 1!
Feb 08, 2020 04:38:42.912 [0x7fa00f7d6700] DEBUG - [Now] User is nuffsaid21 (ID: 1)
Feb 08, 2020 04:38:42.912 [0x7fa00f7d6700] DEBUG - [Now] Device is iOS (Hamam’s iPad).
Feb 08, 2020 04:38:42.912 [0x7fa00f7d6700] DEBUG - [Now] Profile is iOS
Feb 08, 2020 04:38:38.667 [0x7fa0affff700] DEBUG - Auth: authenticated user 1 as nuffsaid21
Feb 08, 2020 04:38:38.668 [0x7fa00f7d6700] DEBUG - Request: [192.168.10.106:56401 (Allowed Network (Subnet))] GET /:/timeline?ratingKey=2101&key=%2Flibrary%2Fmetadata%2F2101&playbackTime=114580&playQueueItemID=9308&state=paused&hasMDE=1&time=114000&duration=2787000 (51 live) TLS GZIP Signed-in Token (nuffsaid21)
Feb 08, 2020 04:38:38.669 [0x7fa00f7d6700] DEBUG - Client [y8ijryrq83n4g4dalrqrnhtu] reporting timeline state paused, progress of 114000/2787000ms for guid=, ratingKey=2101 url=, key=/library/metadata/2101, containerKey=, metadataId=2101, source=
Feb 08, 2020 04:38:38.671 [0x7fa00f7d6700] DEBUG - Play progress on 2101 'Abu Bakr becomes the first caliph, Battle against people not paying Zakat' - got played 114000 ms by account 1!
Feb 08, 2020 04:38:38.673 [0x7fa00f7d6700] DEBUG - [Now] User is nuffsaid21 (ID: 1)
Feb 08, 2020 04:38:38.673 [0x7fa00f7d6700] DEBUG - [Now] Device is Chrome (Chrome).
Feb 08, 2020 04:38:38.673 [0x7fa00f7d6700] DEBUG - [Now] Profile is Web
Feb 08, 2020 04:38:38.673 [0x7fa00f7d6700] DEBUG - [Now] Updated play state for /library/metadata/2101.
Feb 08, 2020 04:38:38.673 [0x7fa00f7d6700] DEBUG - Statistics: (aig99tf00xhmzructt0jbeyi) Reporting active playback in state 1 of type 4 (scrobble: 0) for account 1
Feb 08, 2020 04:38:38.674 [0x7fa0b4c47700] DEBUG - Completed: [192.168.10.106:56401] 200 GET /:/timeline?ratingKey=2101&key=%2Flibrary%2Fmetadata%2F2101&playbackTime=114580&playQueueItemID=9308&state=paused&hasMDE=1&time=114000&duration=2787000 (51 live) TLS GZIP 7ms 533 bytes (pipelined: 125)
Feb 08, 2020 04:38:38.689 [0x7fa0affff700] DEBUG - Auth: authenticated user 1 as nuffsaid21
Feb 08, 2020 04:38:38.690 [0x7fa0107d8700] DEBUG - Request: [192.168.10.106:56401 (Allowed Network (Subnet))] GET /status/sessions (51 live) TLS GZIP Signed-in Token (nuffsaid21)
Feb 08, 2020 04:38:38.690 [0x7fa0107d8700] DEBUG - [Now] Adding 2 sessions.
Feb 08, 2020 04:38:38.691 [0x7fa0affff700] DEBUG - Completed: [192.168.10.106:56401] 200 GET /status/sessions (51 live) TLS GZIP 1ms 2179 bytes (pipelined: 126)
Feb 08, 2020 04:38:38.998 [0x7fa00ffd7700] DEBUG - Request: [127.0.0.1:49906 (Loopback)] PUT /video/:/transcode/session/027D3F00-4FFA-4737-A4CB-AE2973219E1B/b8e870e5-2879-45ad-9fe6-59fbed5a3dbd/progress?progress=64.3&size=-22&remaining=6737 (51 live) Signed-in Token (nuffsaid21) (range: bytes=0-) 
Feb 08, 2020 04:38:38.998 [0x7fa0b4c47700] DEBUG - Completed: [127.0.0.1:49906] 206 PUT /video/:/tra

From everything I’m seeing here, Everything the server is asked to do, it does.

To check the boxes:

  1. Good WiFi signal?
  2. Apps recently updated?

I am in EST-US timezone.

WIFI siginal is good - AP is located in the same room. I did update plex server to latest as the issue was occurring with previous release. Will check IPAD plex if any update is available.

laptop updated Chrome.
Ipad says plex was updated 2 days ago.

Would you please checkx the server timezone setting. It looks +/- GMT
also please make sure it has NTP enabled. strange things happen if time is off.

Checking into those right now.

@htpc:/$ timedatectl
                      Local time: Sat 2020-02-08 00:56:48 EST
                  Universal time: Sat 2020-02-08 05:56:48 UTC
                        RTC time: Sat 2020-02-08 05:56:48
                       Time zone: America/New_York (EST, -0500)
       System clock synchronized: yes
systemd-timesyncd.service active: yes
                 RTC in local TZ: no

was on UTC and fixed to correct timzone.