(FreeBSD) - Plex Media Server process keeps crashing with no log output

Plex Media Server NAS & Devices
,
1

I’ve been hosting Plex for many years on several machines but I’ve never come across this issue. The machine is running FreeNAS 11.1 and Plex is running in a jail. It’s installed via pkg.

ISSUE:
The Plex Media Server process randomly crashes. It can run for weeks and suddenly just be gone from the list of running processes.

Here is a ps ax output just after a crash:

  PID TT  STAT      TIME COMMAND                                                                                                    
15024  -  SsJ    0:01.14 /usr/sbin/syslogd -s                                                                                       
15227  -  SsJ    0:02.54 /usr/sbin/cron -s                                                                                          
15482  -  INJ    4:21.62 Plex Plug-in [com.plexapp.system] /usr/local/share/plexmediaserver/Resources/Plug-ins-200287a06/Framework.b
17147  -  IJ    13:00.92 /usr/local/share/plexmediaserver/Plex DLNA Server                                                          
17149  -  IJ     0:13.14 /usr/local/share/plexmediaserver/Plex Tuner Service /usr/local/share/plexmediaserver/Resources/Tuner/Privat
17150  -  IJ   153:16.28 Plex Plug-in [com.plexapp.agents.subzero] /usr/local/share/plexmediaserver/Resources/Plug-ins-200287a06/Fra
28413  -  IWJ    0:00.00 Plex EAE Service (EasyAudioEncoder)                                                                        
31736  -  IWJ    0:00.00 /bin/sh /etc/periodic/daily/480.leapfile-ntpd                                                              
31740  -  IWJ    0:00.00 sleep 58424                                                                                                
46310  -  IJ     0:08.03 Plex Plug-in [com.plexapp.agents.localmedia] /usr/local/share/plexmediaserver/Resources/Plug-ins-200287a06/
46316  -  IJ     0:07.65 Plex Plug-in [com.plexapp.agents.thetvdb] /usr/local/share/plexmediaserver/Resources/Plug-ins-200287a06/Fra
62138  -  INJ    0:16.64 Plex Plug-in [com.plexapp.system] /usr/local/share/plexmediaserver/Resources/Plug-ins-200287a06/Framework.b
62143  -  IJ     0:02.83 /usr/local/share/plexmediaserver/Plex DLNA Server                                                          
62144  -  IJ     0:00.16 /usr/local/share/plexmediaserver/Plex Tuner Service /usr/local/share/plexmediaserver/Resources/Tuner/Privat
62145  -  IJ     7:29.03 Plex Plug-in [com.plexapp.agents.subzero] /usr/local/share/plexmediaserver/Resources/Plug-ins-200287a06/Fra
62489  -  IJ     0:02.98 Plex EAE Service (EasyAudioEncoder)                                                                        
72143  0  SsJ    0:00.02 /bin/csh                                                                                                   
72447  0  R+J    0:00.00 ps ax

Note that the other Plex related processes are running but the Plex Media Server process is just gone.

The weird thing is that I don’t see anything in the logs either. Here are the last lines of the Plex Media Server.log file after the crash.

Aug 19, 2018 14:57:34.462 [0x80af4c100] DEBUG - handleStreamRead code 335544539: short read                                         
Aug 19, 2018 14:57:34.469 [0x80af4c100] DEBUG - Auth: authenticated user 1 as parski                                                
Aug 19, 2018 14:57:34.470 [0x80d734800] DEBUG - Request: [10.110.110.141:60009 (Subnet)] GET /player/proxy/poll?deviceClass=pc&proto
colVersion=1&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (6 live) TLS GZIP Signed-in Token
 (parski)                                                                                                                           
Aug 19, 2018 14:57:34.470 [0x80d734800] DEBUG - Beginning read from two-way stream.                                                 
Aug 19, 2018 14:57:34.889 [0x80e476f00] DEBUG - Request: [127.0.0.1:41665 (Loopback)] GET /library/metadata/7551 (7 live) GZIP Signe
d-in Token (parski)                                                                                                                 
Aug 19, 2018 14:57:34.894 [0x80e476f00] DEBUG - We're going to try to auto-select an audio stream for account 1.                    
Aug 19, 2018 14:57:34.894 [0x80e476f00] DEBUG - Selecting best audio stream for part ID 10798 (autoselect: 0 language: en)          
Aug 19, 2018 14:57:34.894 [0x80e476f00] DEBUG - Audio Stream: 25118, Subtitle Stream: -1                                            
Aug 19, 2018 14:57:34.895 [0x80af4c100] DEBUG - Completed: [127.0.0.1:41665] 200 GET /library/metadata/7551 (7 live) GZIP 6ms 1690 b
ytes                                                                                                                                
Aug 19, 2018 14:57:34.901 [0x80d734800] DEBUG - Request: [127.0.0.1:41666 (Loopback)] GET /library/metadata/7551 (7 live) GZIP Signe
d-in Token (parski)                                                                                                                 
Aug 19, 2018 14:57:34.906 [0x80d734800] DEBUG - We're going to try to auto-select an audio stream for account 1.                    
Aug 19, 2018 14:57:34.906 [0x80d734800] DEBUG - Selecting best audio stream for part ID 10798 (autoselect: 0 language: en)          
Aug 19, 2018 14:57:34.906 [0x80d734800] DEBUG - Audio Stream: 25118, Subtitle Stream: -1                                            
Aug 19, 2018 14:57:34.907 [0x80af4c100] DEBUG - Completed: [127.0.0.1:41666] 200 GET /library/metadata/7551 (7 live) GZIP 6ms 1690 b
ytes                                                                                                                                
Aug 19, 2018 14:57:34.912 [0x80e476f00] DEBUG - Request: [127.0.0.1:41667 (Loopback)] GET /library/metadata/7472 (7 live) GZIP Signe
d-in Token (parski)                                                                                                                 
Aug 19, 2018 14:57:34.919 [0x80e476f00] DEBUG - There were 1 top-level paths for Futurama.                                          
Aug 19, 2018 14:57:34.919 [0x80af4c100] DEBUG - Completed: [127.0.0.1:41667] 200 GET /library/metadata/7472 (7 live) GZIP 7ms 1647 b
ytes                                                                                                                                
Aug 19, 2018 14:57:34.926 [0x80d734800] DEBUG - Request: [127.0.0.1:41668 (Loopback)] GET /library/metadata/7551 (7 live) GZIP Signe
d-in Token (parski)                                                                                                                 
Aug 19, 2018 14:57:34.931 [0x80d734800] DEBUG - We're going to try to auto-select an audio stream for account 1.                    
Aug 19, 2018 14:57:34.931 [0x80d734800] DEBUG - Selecting best audio stream for part ID 10798 (autoselect: 0 language: en)          
Aug 19, 2018 14:57:34.931 [0x80d734800] DEBUG - Audio Stream: 25118, Subtitle Stream: -1                                            
Aug 19, 2018 14:57:34.932 [0x80af4c100] DEBUG - Completed: [127.0.0.1:41668] 200                                                    
 GET /library/metadata/7551 (7 live) GZIP 6ms 1690 bytes                                                                            
Aug 19, 2018 14:57:35.942 [0x80e478800] DEBUG - Checking if time for scheduled update                                               
Aug 19, 2018 14:57:35.943 [0x80e478800] INFO - It's been 1199 seconds, so we're starting scheduled library update for section 10 (Mo
vies)                                                                                                                               
Aug 19, 2018 14:57:35.943 [0x80e478800] DEBUG - Library Updater: Requested that section 10 be updated, force=0, deep=0, subdir= iTun
es=0                                                                                                                                
Aug 19, 2018 14:57:35.943 [0x80e478800] DEBUG - Library Updater: Queueing section 10                                                
Aug 19, 2018 14:57:35.943 [0x80e478800] INFO - It's been 1199 seconds, so we're starting scheduled library update for section 11 (TV
 Shows)                                                                                                                             
Aug 19, 2018 14:57:35.944 [0x80e478800] DEBUG - Library Updater: Requested that section 11 be updated, force=0, deep=0, subdir= iTun
es=0                                                                                                                                
Aug 19, 2018 14:57:35.945 [0x80e478800] DEBUG - Library Updater: Queueing section 11                                                
Aug 19, 2018 14:57:35.945 [0x80cc47500] DEBUG - Scanning section 10                                                                 
Aug 19, 2018 14:57:35.945 [0x80cc47500] DEBUG - Killing job.                                                                        
Aug 19, 2018 14:57:35.945 [0x80cc47500] DEBUG - Signalling job ID 70551 with 9                                                      
Aug 19, 2018 14:57:35.945 [0x80cc47500] DEBUG - Job running: EAE_ROOT='/tmp/pms-23fa7688-9747-48b8-b0b3-8b60c82d0220/EasyAudioEncode
r' FFMPEG_EXTERNAL_LIBS='/usr/local/plexdata/Plex\ Media\ Server/Codecs/e944d3a-1309-freebsd-x86_64/' X_PLEX_TOKEN='xxxxxxxxxxxxxxxx
xxxx' '/usr/local/share/plexmediaserver/Plex Media Scanner' '--scan' '--refresh' '--section' '10'

I’ve set up a watchdog script that just notes when the server goes down but it hasn’t made me any wiser. How can I find out why the process is dying and what to do about it? Has anyone else had this issue?

Server Version#: 1.13.4.5271
Player Version#: Not applicable

2

It happened again today. Here is the last second or so from the log file:

Aug 21, 2018 12:49:18.703 [0x80b3afc00] DEBUG - Collections: Found 0 collections tags in section 10.                                
Aug 21, 2018 12:49:18.703 [0x80b3afc00] DEBUG - Collections: We had 0 collections in the library already.                           
Aug 21, 2018 12:49:18.703 [0x80b3afc00] DEBUG - Collections: Synced tags in section 10 in 0ms.                                      
Aug 21, 2018 12:49:18.703 [0x80b3afc00] DEBUG - Collections: Refreshed attributes for 0 collections in section 10 in 0ms.           
Aug 21, 2018 12:49:18.704 [0x80b3afc00] DEBUG - Collection: Refreshed visibility in section 10 in 0ms.                              
Aug 21, 2018 12:49:18.705 [0x80ea66900] DEBUG - Activity: registered new activity 8df4e852-33e4-4464-b78e-9e37a2323fe7 - Processing 
subscriptions                                                                                                                       
Aug 21, 2018 12:49:18.706 [0x80ea66900] DEBUG - Scanning section 14                                                                 
Aug 21, 2018 12:49:18.706 [0x80ea66900] DEBUG - Killing job.                                                                        
Aug 21, 2018 12:49:18.706 [0x80ea66900] DEBUG - Signalling job ID 25511 with 9                                                      
Aug 21, 2018 12:49:18.706 [0x80ea66900] DEBUG - Job running: EAE_ROOT='/tmp/pms-bc755c73-8cc9-460a-8fd0-51116a029c06/EasyAudioEncode
r' FFMPEG_EXTERNAL_LIBS='/usr/local/plexdata/Plex\ Media\ Server/Codecs/e944d3a-1309-freebsd-x86_64/' X_PLEX_TOKEN='xxxxxxxxxxxxxxxx
xxxx' '/usr/local/share/plexmediaserver/Plex Media Scanner' '--scan' '--refresh' '--section' '14'                                   
Aug 21, 2018 12:49:18.706 [0x80e673000] DEBUG - Activity: registered new activity c5de70d0-9fb1-40b5-a540-d53f49655ebe - Processing 
subscriptions                                                                                                                       
Aug 21, 2018 12:49:18.718 [0x80e673000] DEBUG - DVR:Subscription: Scheduling subscriptions.                                         
Aug 21, 2018 12:49:18.718 [0x80ea66900] DEBUG - Jobs: Starting child process with pid 25512                                         
Aug 21, 2018 12:49:18.719 [0x80e673000] DEBUG - DVR:Subscription: Initialized 0 schedulers.                                         
Aug 21, 2018 12:49:18.719 [0x80e673000] DEBUG - DVR:Subscription: Starting with 0 grabs, scheduled 0 active ones preemptively.      
Aug 21, 2018 12:49:18.719 [0x80e673000] DEBUG - DVR:Subscription: Scheduled all subscriptions in 1 ms.                              
Aug 21, 2018 12:49:18.720 [0x80e673000] DEBUG - Activity: Ended activity c5de70d0-9fb1-40b5-a540-d53f49655ebe.                      
Aug 21, 2018 12:49:18.720 [0x80e673000] DEBUG - DVR:Subscription: There are 0 grabs at the end.                                     
Aug 21, 2018 12:49:18.720 [0x80e673000] DEBUG - Activity: Ended activity 8df4e852-33e4-4464-b78e-9e37a2323fe7.                      
Aug 21, 2018 12:49:18.720 [0x80e673000] DEBUG - DVR:Subscription: Refreshed all content in 14 ms.                                   
Aug 21, 2018 12:49:18.885 [0x80af4b200] DEBUG - Request: [127.0.0.1:43190 (Loopback)] GET /:/metadata/notify/cullTimeline?librarySec
tionID=14&sinceTime=1534847358 (7 live) GZIP Signed-in Token (parski)                                                               
Aug 21, 2018 12:49:18.886 [0x80af4b200] DEBUG - Asked to cull library timeline before time 1534847358, we're starting with 4 items. 
Aug 21, 2018 12:49:18.886 [0x80af4b200] DEBUG - Library timeline cull complete with 4 items left.                                   
Aug 21, 2018 12:49:18.886 [0x80af4c600] DEBUG - Completed: [127.0.0.1:43190] 200 GET /:/metadata/notify/cullTimeline?librarySectionI
D=14&sinceTime=1534847358 (7 live) GZIP 0ms 166 bytes                                                                               
Aug 21, 2018 12:49:19.004 [0x80fa8b000] DEBUG - Request: [127.0.0.1:43191 (Loopback)] GET /:/metadata/updateProgressMessage?message=
Scanning%20Dan%20Carlin%20-%20Hardcore%20History (7 live) GZIP Signed-in Token (parski)                                             
Aug 21, 2018 12:49:19.005 [0x80af4c100] DEBUG - Completed: [127.0.0.1:43191] 200 GET /:/metadata/updateProgressMessage?message=Scann
ing%20Dan%20Carlin%20-%20Hardcore%20History (7 live) GZIP 0ms 166 bytes                                                             
Aug 21, 2018 12:49:19.017 [0x80b3afc00] DEBUG - Jobs: '/usr/local/share/plexmediaserver/Plex Media Scanner' exit code for process 25
512 is 0 (success)                                                                                                                  
Aug 21, 2018 12:49:19.018 [0x80ea66900] DEBUG - Activity: registered new activity ec08085f-0836-4729-bceb-9bab22b439af - Processing 
subscriptions                                                                                                                       
Aug 21, 2018 12:49:19.019 [0x80ea66900] DEBUG - Scanning section 11                                                                 
Aug 21, 2018 12:49:19.019 [0x80ea66900] DEBUG - Killing job.                                                                        
Aug 21, 2018 12:49:19.019 [0x80ea66900] DEBUG - Signalling job ID 25512 with 9                                                      
Aug 21, 2018 12:49:19.019 [0x80ea66900] DEBUG - Job running: EAE_ROOT='/tmp/pms-bc755c73-8cc9-460a-8fd0-51116a029c06/EasyAudioEncode
r' FFMPEG_EXTERNAL_LIBS='/usr/local/plexdata/Plex\ Media\ Server/Codecs/e944d3a-1309-freebsd-x86_64/' X_PLEX_TOKEN='xxxxxxxxxxxxxxxx
xxxx' '/usr/local/share/plexmediaserver/Plex Media Scanner' '--scan' '--refresh' '--section' '11'                                   
Aug 21, 2018 12:49:19.019 [0x80e673000] DEBUG - Activity: registered new activity f32a80f6-28dc-4299-a62e-681543393441 - Processing 
subscriptions                                                                                                                       
Aug 21, 2018 12:49:19.019 [0x80e673000] DEBUG - DVR:Subscription: Scheduling subscriptions.                                         
Aug 21, 2018 12:49:19.020 [0x80e673000] DEBUG - DVR:Subscription: Initialized 0 schedulers.                                         
Aug 21, 2018 12:49:19.020 [0x80e673000] DEBUG - DVR:Subscription: Starting with 0 grabs, scheduled 0 active ones preemptively.

Could the scanner be triggering the crash?

3

It just crashed again half an hour ago. Here are the last few lines of Plex Media Server.log:

Aug 25, 2018 22:05:24.600 [0x80af4d600] DEBUG - Completed: [10.110.110.141:50998] 200 GET /myplex/account (11 live) TLS GZIP 0ms 167
2 bytes (pipelined: 1)                                                                                                              
Aug 25, 2018 22:05:24.636 [0x80af4d100] DEBUG - Auth: authenticated user 1 as parski                                                
Aug 25, 2018 22:05:24.636 [0x80b6bf000] DEBUG - Request: [10.110.110.141:50997 (Subnet)] GET /myplex/account (11 live) TLS GZIP Sign
ed-in Token (parski)                                                                                                                
Aug 25, 2018 22:05:24.637 [0x80af4d600] DEBUG - Auth: authenticated user 1 as parski                                                
Aug 25, 2018 22:05:24.637 [0x80b6bf000] DEBUG - Request: [10.110.110.141:50998 (Subnet)] GET /myplex/account (11 live) TLS GZIP Sign
ed-in Token (parski)                                                                                                                
Aug 25, 2018 22:05:24.637 [0x80af4d100] DEBUG - Completed: [10.110.110.141:50997] 200 GET /myplex/account (11 live) TLS GZIP 0ms 167
2 bytes (pipelined: 2)                                                                                                              
Aug 25, 2018 22:05:24.638 [0x80af4d100] DEBUG - Completed: [10.110.110.141:50998] 200 GET /myplex/account (11 live) TLS GZIP 0ms 167
2 bytes (pipelined: 2)                                                                                                              
Aug 25, 2018 22:05:26.192 [0x80af4d100] DEBUG - Auth: authenticated user 9524007 as tejp                                            
Aug 25, 2018 22:05:26.192 [0x80b6bf000] DEBUG - Request: [31.208.69.232:54918 (WAN)] GET /clients (12 live) TLS Signed-in Token (tej
p)                                                                                                                                  
Aug 25, 2018 22:05:26.193 [0x80af4d100] DEBUG - Completed: [31.208.69.232:54918] 200 GET /clients (12 live) TLS 0ms 579 bytes (pipel
ined: 1)                                                                                                                            
Aug 25, 2018 22:05:40.127 [0x80af4d100] DEBUG - handleStreamRead code 335544539: short read                                         
Aug 25, 2018 22:05:40.132 [0x80af4d600] DEBUG - Auth: authenticated user 1 as parski                                                
Aug 25, 2018 22:05:40.133 [0x80c417000] DEBUG - Request: [10.110.110.141:50997 (Subnet)] GET /player/proxy/poll?deviceClass=pc&proto
colVersion=1&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (11 live) TLS GZIP Signed-in Toke
n (parski)                                                                                                                          
Aug 25, 2018 22:05:40.133 [0x80c417000] DEBUG - Beginning read from two-way stream.                                                 
Aug 25, 2018 22:06:00.235 [0x80af4d100] DEBUG - handleStreamRead code 335544539: short read                                         
Aug 25, 2018 22:06:00.245 [0x80af4d600] DEBUG - Auth: authenticated user 1 as parski                                                
Aug 25, 2018 22:06:00.246 [0x80e6d6800] DEBUG - Request: [10.110.110.141:51023 (Subnet)] GET /player/proxy/poll?deviceClass=pc&proto
colVersion=1&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (9 live) TLS GZIP Signed-in Token
 (parski)                                                                                                                           
Aug 25, 2018 22:06:00.246 [0x80e6d6800] DEBUG - Beginning read from two-way stream.                                                 
Aug 25, 2018 22:06:02.163 [0x80b3b4300] DEBUG - Checking if time for scheduled update                                               
Aug 25, 2018 22:06:02.163 [0x80b3b4300] INFO - It's been 900 seconds, so we're starting scheduled library update for section 15 (Aud
io Books)                                                                                                                           
Aug 25, 2018 22:06:02.163 [0x80b3b4300] DEBUG - Library Updater: Requested that section 15 be updated, force=0, deep=0, subdir= iTun
es=0                                                                                                                                
Aug 25, 2018 22:06:02.163 [0x80b3b4300] DEBUG - Library Updater: Queueing section 15                                                
Aug 25, 2018 22:06:02.164 [0x80b3b4300] INFO - It's been 1199 seconds, so we're starting scheduled library update for section 11 (TV
 Shows)                                                                                                                             
Aug 25, 2018 22:06:02.165 [0x80b3b4300] DEBUG - Library Updater: Requested that section 11 be updated, force=0, deep=0, subdir= iTun
es=0                                                                                                                                
Aug 25, 2018 22:06:02.165 [0x80b3b4300] DEBUG - Library Updater: Queueing section 11                                                
Aug 25, 2018 22:06:02.165 [0x80b3b5c00] DEBUG - Scanning section 15                                                                 
Aug 25, 2018 22:06:02.166 [0x80b3b5c00] DEBUG - Killing job.                                                                        
Aug 25, 2018 22:06:02.166 [0x80b3b5c00] DEBUG - Signalling job ID 81320 with 9                                                      
Aug 25, 2018 22:06:02.166 [0x80b3b5c00] DEBUG - Job running: EAE_ROOT='/tmp/pms-3ad9b0d1-af64-4d07-8706-e65177ee94ce/EasyAudioEncode
r' FFMPEG_EXTERNAL_LIBS='/usr/local/plexdata/Plex\ Media\ Server/Codecs/e944d3a-1309-freebsd-x86_64/' X_PLEX_TOKEN='xxxxxxxxxxxxxxxx
xxxx' '/usr/local/share/plexmediaserver/Plex Media Scanner' '--scan' '--refresh' '--section' '15'                                   
Aug 25, 2018 22:06:02.181 [0x80b3b5c00] DEBUG - Jobs: Starting child process with pid 81486                                         
Aug 25, 2018 22:06:02.184 [0x80af4d600] DEBUG - Auth: authenticated user 1 as parski

Again one of the last things to happen is:

DEBUG - Job running: EAE_ROOT='/tmp/pms-3ad9b0d1-af64-4d07-8706-e65177ee94ce/EasyAudioEncode
r' FFMPEG_EXTERNAL_LIBS='/usr/local/plexdata/Plex\ Media\ Server/Codecs/e944d3a-1309-freebsd-x86_64/' X_PLEX_TOKEN='xxxxxxxxxxxxxxxx
xxxx' '/usr/local/share/plexmediaserver/Plex Media Scanner' '--scan' '--refresh' '--section' '15'

It seems to be different sections every time though.

Looking at the most recent scanner’s log (Plex Media Scanner.log) I don’t see anything indicating a fatal crash of another process:

Aug 25, 2018 22:06:02.237 [0x8092b5400] INFO - Plex Media Scanner v1.13.4.5271-200287a06 - FreeBSD PC amd64 - build: freebsd-x86_64 
- GMT 02:00                                                                                                                         
Aug 25, 2018 22:06:02.239 [0x8092b5400] ERROR - Failed to determine system locale: locale::facet::_S_create_c_locale name not valid.
 Defaulting to en-US.                                                                                                               
Aug 25, 2018 22:06:02.239 [0x8092b5400] INFO - FreeBSD version: 11.0-RELEASE (FreeBSD 11.1-STABLE #0 r321665+e0c4ca60dfc(freenas/11.
1-stable): Wed May 30 14:18:20 EDT 2018     root@nemesis.tn.ixsystems.com:/freenas-11-releng/freenas/_BE/objs/freenas-11-releng/free
nas/_BE/os/sys/FreeNAS.amd64), language: en-US                                                                                      
Aug 25, 2018 22:06:02.239 [0x8092b5400] INFO - Processor AMD EPYC 7401P 24-Core Processor                                           
Aug 25, 2018 22:06:02.239 [0x8092b5400] INFO - /usr/local/share/plexmediaserver/Plex Media Scanner --scan --refresh --section 15    
Aug 25, 2018 22:06:02.232 [0x809218000] WARN - Default locale is invalid; falling back on classic+UTF-8                             
Aug 25, 2018 22:06:02.240 [0x809218000] DEBUG - Opening 20 database sessions to library (com.plexapp.plugins.library), SQLite 3.13.0
, threadsafe=1                                                                                                                      
Aug 25, 2018 22:06:02.243 [0x809218000] INFO - SQLITE3:0x10, 283, recovered 736 frames from WAL file /usr/local/plexdata/Plex Media 
Server/Plug-in Support/Databases/com.plexapp.plugins.library.db-wal                                                                 
Aug 25, 2018 22:06:02.367 [0x809218000] DEBUG - Scanning Audio Books using en(Plex Music Scanner) with 0 current media items and 1 s
ection locations in the database...                                                                                                 
Aug 25, 2018 22:06:02.367 [0x80f2edf00] DEBUG - HTTP requesting GET http://127.0.0.1:32400/:/metadata/notify/cullTimeline?librarySec
tionID=15&sinceTime=1535226362                                                                                                      
Aug 25, 2018 22:06:02.368 [0x80f2edf00] ERROR - Error issuing curl_easy_perform(handle): 7                                          
Aug 25, 2018 22:06:02.368 [0x80f2edf00] WARN - HTTP error requesting GET http://127.0.0.1:32400/:/metadata/notify/cullTimeline?libra
rySectionID=15&sinceTime=1535226362 (0, No error) (Failed connect to 127.0.0.1:32400; Connection refused)                           
Aug 25, 2018 22:06:02.478 [0x809218000] DEBUG - Performing a scan with 'Plex Music Scanner' (language: en virtual: 0).              
Aug 25, 2018 22:06:02.478 [0x809218000] DEBUG -   * Scanning /mnt/pool/Audio Books                                                  
Aug 25, 2018 22:06:02.478 [0x809218000] DEBUG -   * Marking media not available in /mnt/pool/Audio Books                            
Aug 25, 2018 22:06:02.480 [0x809218000] DEBUG -   * Taking 0 items out of the map (which has 0 items) for being unavailable.        
Aug 25, 2018 22:06:02.481 [0x809218000] DEBUG -   * Taking 0 directories out of the map (which has 0 dirs) for being unavailable.   
Aug 25, 2018 22:06:02.483 [0x809218000] DEBUG - Removing 0 media items that were left.                                              
Aug 25, 2018 22:06:02.483 [0x809218000] DEBUG - Removing 0 directories that were left.                                              
Aug 25, 2018 22:06:02.485 [0x809218000] DEBUG - Refreshing section 15 of type: 8                                                    
Aug 25, 2018 22:06:02.486 [0x80f2eee00] DEBUG - Refreshing 0 IDs.

The only thing that looks really suspicious is the curl error and the subsequent warning:

Aug 25, 2018 22:06:02.368 [0x80f2edf00] ERROR - Error issuing curl_easy_perform(handle): 7                                          
Aug 25, 2018 22:06:02.368 [0x80f2edf00] WARN - HTTP error requesting GET http://127.0.0.1:32400/:/metadata/notify/cullTimeline?libra
rySectionID=15&sinceTime=1535226362 (0, No error) (Failed connect to 127.0.0.1:32400; Connection refused)

Maybe they are both due to the Plex Media Server process having crashed? Who knows? It’s log says nothing…

4

And again. This time no scanner involved it seems?

Plex Media Server.log:

Aug 26, 2018 00:30:48.471 [0x80b3d4700] DEBUG - Selecting best audio stream for part ID 10409 (autoselect: 0 language: en)          
Aug 26, 2018 00:30:48.471 [0x80b3d4700] DEBUG - Audio Stream: 23296, Subtitle Stream: 23297                                         
Aug 26, 2018 00:30:48.471 [0x80b3d4700] DEBUG - We're going to try to auto-select an audio stream for account 1.                    
Aug 26, 2018 00:30:48.471 [0x80b3d4700] DEBUG - Selecting best audio stream for part ID 10386 (autoselect: 0 language: en)          
Aug 26, 2018 00:30:48.471 [0x80b3d4700] DEBUG - Audio Stream: 23212, Subtitle Stream: -1                                            
Aug 26, 2018 00:30:48.472 [0x80b3d4700] DEBUG - We're going to try to auto-select an audio stream for account 1.                    
Aug 26, 2018 00:30:48.472 [0x80b3d4700] DEBUG - Selecting best audio stream for part ID 10385 (autoselect: 0 language: en)          
Aug 26, 2018 00:30:48.472 [0x80b3d4700] DEBUG - Audio Stream: 23209, Subtitle Stream: 23210                                         
Aug 26, 2018 00:30:48.472 [0x80b3d4700] DEBUG - We're going to try to auto-select an audio stream for account 1.                    
Aug 26, 2018 00:30:48.472 [0x80b3d4700] DEBUG - Selecting best audio stream for part ID 10384 (autoselect: 0 language: en)          
Aug 26, 2018 00:30:48.472 [0x80b3d4700] DEBUG - Audio Stream: 23205, Subtitle Stream: -1                                            
Aug 26, 2018 00:30:48.473 [0x80b3d4700] DEBUG - We're going to try to auto-select an audio stream for account 1.                    
Aug 26, 2018 00:30:48.473 [0x80b3d4700] DEBUG - Selecting best audio stream for part ID 10258 (autoselect: 0 language: en)          
Aug 26, 2018 00:30:48.473 [0x80b3d4700] DEBUG - Audio Stream: 23017, Subtitle Stream: -1                                            
Aug 26, 2018 00:30:48.475 [0x80b3d4700] DEBUG - There were 1 top-level paths for Attack on Titan.                                   
Aug 26, 2018 00:30:48.475 [0x80b3d4700] DEBUG - We're going to try to auto-select an audio stream for account 1.                    
Aug 26, 2018 00:30:48.475 [0x80b3d4700] DEBUG - Selecting best audio stream for part ID 9943 (autoselect: 0 language: en)           
Aug 26, 2018 00:30:48.475 [0x80b3d4700] DEBUG - Audio Stream: 22251, Subtitle Stream: -1                                            
Aug 26, 2018 00:30:48.476 [0x80b3d4700] DEBUG - There were 1 top-level paths for Naked and Afraid XL.                               
Aug 26, 2018 00:30:48.476 [0x80b3d4700] DEBUG - We're going to try to auto-select an audio stream for account 1.                    
Aug 26, 2018 00:30:48.476 [0x80b3d4700] DEBUG - Selecting best audio stream for part ID 9930 (autoselect: 0 language: en)           
Aug 26, 2018 00:30:48.476 [0x80b3d4700] DEBUG - Audio Stream: 22205, Subtitle Stream: -1                                            
Aug 26, 2018 00:30:48.481 [0x80b3d4700] DEBUG - There were 2 top-level paths for Hunter x Hunter (2011).                            
Aug 26, 2018 00:30:48.483 [0x80b3d4700] DEBUG - There were 1 top-level paths for Neon Genesis Evangelion.                           
Aug 26, 2018 00:30:48.484 [0x80b3d4700] DEBUG - We're going to try to auto-select an audio stream for account 1.                    
Aug 26, 2018 00:30:48.484 [0x80b3d4700] DEBUG - Selecting best audio stream for part ID 9510 (autoselect: 0 language: en)           
Aug 26, 2018 00:30:48.484 [0x80b3d4700] DEBUG - Audio Stream: 20834, Subtitle Stream: -1                                            
Aug 26, 2018 00:30:48.486 [0x80b3d4700] DEBUG - There were 1 top-level paths for Twin Peaks.                                        
Aug 26, 2018 00:30:48.493 [0x80b3d4700] DEBUG - There were 1 top-level paths for King of the Hill.                                  
Aug 26, 2018 00:30:48.503 [0x80af4d600] DEBUG - Completed: [10.110.110.141:59098] 200 GET /hubs/home/recentlyAdded?type=2 (24 live) 
TLS GZIP Page 0-47 155ms 29806 bytes (pipelined: 17)                                                                                
Aug 26, 2018 00:30:50.374 [0x80af4d100] DEBUG - Completed: [10.110.110.141:59099] 200 GET /hubs/metadata/6240/related?excludeFields=
summary&count=12 (17 live) TLS GZIP 3383ms 3451487 bytes (pipelined: 1)                                                             
Aug 26, 2018 00:30:52.062 [0x80af4d100] DEBUG - Auth: authenticated user 1 as parski                                                
Aug 26, 2018 00:30:52.062 [0x80d532000] DEBUG - Request: [10.110.110.141:59099 (Subnet)] GET /library/metadata/6240/similar (16 live
) TLS Page 12-38 GZIP Signed-in Token (parski)                                                                                      
Aug 26, 2018 00:30:52.114 [0x80d532000] DEBUG - It took 0.000000 ms to retrieve 117 items.                                          
Aug 26, 2018 00:30:52.124 [0x80d532000] DEBUG - It took 7.812500 ms to retrieve 111 items.                                          
Aug 26, 2018 00:30:52.146 [0x80d532000] DEBUG - Setting container serialization range to [12, 38] (total=-1)                        
Aug 26, 2018 00:30:52.147 [0x80af4d600] DEBUG - Completed: [10.110.110.141:59099] 200 GET /library/metadata/6240/similar (16 live) T
LS GZIP Page 12-38 85ms 595 bytes (pipelined: 2)                                                                                    
Aug 26, 2018 00:30:53.955 [0x80af4d100] DEBUG - handleStreamRead code 335544539: short read                                         
Aug 26, 2018 00:30:53.959 [0x80af4d600] DEBUG - Auth: authenticated user 1 as parski                                                
Aug 26, 2018 00:30:53.959 [0x80e276500] DEBUG - Request: [10.110.110.141:59099 (Subnet)] GET /player/proxy/poll?deviceClass=pc&proto
colVersion=1&protocolCapabilities=timeline%2Cplayback%2Cnavigation%2Cmirror%2Cplayqueues&timeout=1 (15 live) TLS GZIP Signed-in Toke
n (parski)                                                                                                                          
Aug 26, 2018 00:30:53.959 [0x80e276500] DEBUG - Beginning read from two-way stream.                                                 
Aug 26, 2018 00:31:07.899 [0x80b6ed500] DEBUG - NetworkServiceBrowser: SSDP departed after not being seen for 21.913238 seconds: 10.
110.110.163

This is really frustrating.

5

And another one. Anyone got any ideas as to how I should go about troubleshooting this?

Aug 26, 2018 20:29:56.985 [0x80af4d600] DEBUG - Completed: [10.110.110.4:45690] 200 PUT /myplex/refreshReachability (8 live) 210ms 1
95 bytes (pipelined: 1)                                                                                                             
Aug 26, 2018 20:29:56.986 [0x80af4d600] DEBUG - Auth: authenticated user 1 as parski                                                
Aug 26, 2018 20:29:56.987 [0x81281ce00] DEBUG - Request: [10.110.110.4:40845 (Subnet)] GET /myplex/account (8 live) Signed-in Token 
(parski)                                                                                                                            
Aug 26, 2018 20:29:56.987 [0x80af4d600] DEBUG - Completed: [10.110.110.4:40845] 200 GET /myplex/account (8 live) 0ms 2297 bytes (pip
elined: 1)                                                                                                                          
Aug 26, 2018 20:29:57.173 [0x80b3d7700] DEBUG - Request: [54.246.248.53:36713 (WAN)] GET /identity (8 live) TLS Signed-in Token (par
ski)                                                                                                                                
Aug 26, 2018 20:29:57.173 [0x80af4d600] DEBUG - Completed: [54.246.248.53:36713] 200 GET /identity (8 live) TLS 0ms 357 bytes       
Aug 26, 2018 20:29:57.355 [0x80af4d600] DEBUG - EventSource: Got event [data] '<Message address="94.255.208.190" port="32402" asyncI
dentifier="1f3820ae-4d2a-4f29-8141-872bd66cf6b3" connectivity="1" command="notifyConnectivity"/>'                                   
Aug 26, 2018 20:29:57.355 [0x80af4d600] WARN - PubSub: Received notifyConnectivity event with incorrect async identifier (1f3820ae-4
d2a-4f29-8141-872bd66cf6b3, expected )                                                                                              
Aug 26, 2018 20:29:57.355 [0x80af4d600] DEBUG - PubSub: Got notified of reachability: 1 for 94.255.208.190:32402                    
Aug 26, 2018 20:29:57.363 [0x80af4d600] DEBUG - Auth: authenticated user 1 as parski                                                
Aug 26, 2018 20:29:57.363 [0x81281ce00] DEBUG - Request: [10.110.110.141:59391 (Subnet)] GET /myplex/account (8 live) TLS GZIP Signe
d-in Token (parski)                                                                                                                 
Aug 26, 2018 20:29:57.364 [0x80af4d600] DEBUG - Completed: [10.110.110.141:59391] 200 GET /myplex/account (8 live) TLS GZIP 0ms 1672
 bytes (pipelined: 1)                                                                                                               
Aug 26, 2018 20:29:57.481 [0x80af4d100] DEBUG - EventSource: Got event [data] '<Message address="94.255.208.190" port="32402" asyncI
dentifier="1f3820ae-4d2a-4f29-8141-872bd66cf6b3" connectivity="1" command="notifyConnectivity"/>'                                   
Aug 26, 2018 20:29:57.481 [0x80af4d100] WARN - PubSub: Received notifyConnectivity event with incorrect async identifier (1f3820ae-4
d2a-4f29-8141-872bd66cf6b3, expected )                                                                                              
Aug 26, 2018 20:29:57.481 [0x80af4d100] DEBUG - PubSub: Got notified of reachability: 1 for 94.255.208.190:32402                    
Aug 26, 2018 20:29:57.486 [0x80af4d600] DEBUG - Auth: authenticated user 1 as parski                                                
Aug 26, 2018 20:29:57.486 [0x81281ce00] DEBUG - Request: [10.110.110.141:59391 (Subnet)] GET /myplex/account (8 live) TLS GZIP Signe
d-in Token (parski)                                                                                                                 
Aug 26, 2018 20:29:57.487 [0x80af4d600] DEBUG - Completed: [10.110.110.141:59391] 200 GET /myplex/account (8 live) TLS GZIP 0ms 1672
 bytes (pipelined: 2)                                                                                                               
Aug 26, 2018 20:30:40.150 [0x81281fb00] DEBUG - Checking if time for scheduled update                                               
Aug 26, 2018 20:30:40.150 [0x81281fb00] INFO - It's been 900 seconds, so we're starting scheduled library update for section 10 (Mov
ies)                                                                                                                                
Aug 26, 2018 20:30:40.150 [0x81281fb00] DEBUG - Library Updater: Requested that section 10 be updated, force=0, deep=0, subdir= iTun
es=0                                                                                                                                
Aug 26, 2018 20:30:40.150 [0x81281fb00] DEBUG - Library Updater: Queueing section 10                                                
Aug 26, 2018 20:30:40.151 [0x81281fb00] INFO - It's been 900 seconds, so we're starting scheduled library update for section 11 (TV 
Shows)                                                                                                                              
Aug 26, 2018 20:30:40.152 [0x81281fb00] DEBUG - Library Updater: Requested that section 11 be updated, force=0, deep=0, subdir= iTun
es=0                                                                                                                                
Aug 26, 2018 20:30:40.152 [0x81281fb00] DEBUG - Library Updater: Queueing section 11                                                
Aug 26, 2018 20:30:40.152 [0x80e254200] DEBUG - Scanning section 10                                                                 
Aug 26, 2018 20:30:40.153 [0x80e254200] DEBUG - Killing job.                                                                        
Aug 26, 2018 20:30:40.153 [0x80e254200] DEBUG - Signalling job ID 60816 with 9                                                      
Aug 26, 2018 20:30:40.153 [0x80e254200] DEBUG - Job running: EAE_ROOT='/tmp/pms-d9532367-0bfc-4ef5-b323-cf97946a81d1/EasyAudioEncode
r' FFMPEG_EXTERNAL_LIBS='/usr/local/plexdata/Plex\ Media\ Server/Codecs/e944d3a-1309-freebsd-x86_64/' X_PLEX_TOKEN='xxxxxxxxxxxxxxxx
xxxx' '/usr/local/share/plexmediaserver/Plex Media Scanner' '--scan' '--refresh' '--section' '10'                                   
Aug 26, 2018 20:30:40.165 [0x80e254200] DEBUG - Jobs: Starting child process with pid 60995

[Edit]

I see a slight bump in CPU activity but nothing unreal. It seems to be after the fact, even.

local

6

It turns out verbose logging isn’t making me wiser.

Aug 29, 2018 21:27:11.547 [0x80e252900] DEBUG - Scanning section 14                                                                 
Aug 29, 2018 21:27:11.547 [0x80e252900] DEBUG - Killing job.                                                                        
Aug 29, 2018 21:27:11.547 [0x80e252900] DEBUG - Signalling job ID 94617 with 9                                                      
Aug 29, 2018 21:27:11.547 [0x80e252900] DEBUG - Job running: EAE_ROOT='/tmp/pms-3e68ea52-e03a-4b4a-bab3-61c116f7a1e8/EasyAudioEncode
r' FFMPEG_EXTERNAL_LIBS='/usr/local/plexdata/Plex\ Media\ Server/Codecs/e944d3a-1309-freebsd-x86_64/' X_PLEX_TOKEN='xxxxxxxxxxxxxxxx
xxxx' '/usr/local/share/plexmediaserver/Plex Media Scanner' '--scan' '--refresh' '--section' '14'                                   
Aug 29, 2018 21:27:11.560 [0x80e252900] DEBUG - Jobs: Starting child process with pid 94769                                         
Aug 29, 2018 21:27:11.728 [0x80af4d100] VERBOSE - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authenticat
ion.                                                                                                                                
Aug 29, 2018 21:27:11.728 [0x80af4d100] VERBOSE - Auth: Came in with the master token, authorization succeeded.                     
Aug 29, 2018 21:27:11.729 [0x80e251500] DEBUG - Request: [127.0.0.1:11315 (Loopback)] GET /:/metadata/notify/cullTimeline?librarySec
tionID=14&sinceTime=1535569631 (10 live) GZIP Signed-in Token (parski)                                                              
Aug 29, 2018 21:27:11.729 [0x80e251500] VERBOSE -  * User-Agent => Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, l
ike Gecko) Chrome/47.0.2526.106 Safari/537.36                                                                                       
Aug 29, 2018 21:27:11.729 [0x80e251500] VERBOSE -  * Host => 127.0.0.1:32400                                                        
Aug 29, 2018 21:27:11.729 [0x80e251500] VERBOSE -  * Accept => */*                                                                  
Aug 29, 2018 21:27:11.729 [0x80e251500] VERBOSE -  * Accept-Encoding => gzip                                                        
Aug 29, 2018 21:27:11.729 [0x80e251500] VERBOSE -  * X-Plex-Token => xxxxxxxxxxxxxxxxxxxx                                           
Aug 29, 2018 21:27:11.729 [0x80e251500] VERBOSE -  * librarySectionID => 14                                                         
Aug 29, 2018 21:27:11.729 [0x80e251500] VERBOSE -  * sinceTime => 1535569631                                                        
Aug 29, 2018 21:27:11.729 [0x80e251500] DEBUG - Asked to cull library timeline before time 1535569631, we're starting with 26 items.
Aug 29, 2018 21:27:11.729 [0x80e251500] DEBUG - Library timeline cull complete with 26 items left.                                  
Aug 29, 2018 21:27:11.729 [0x80af4d100] DEBUG - Completed: [127.0.0.1:11315] 200 GET /:/metadata/notify/cullTimeline?librarySectionI
D=14&sinceTime=1535569631 (9 live) GZIP 0ms 166 bytes                                                                               
Aug 29, 2018 21:27:11.851 [0x80af4d100] VERBOSE - Auth: We found auth token (xxxxxxxxxxxxxxxxxxxx), enabling token-based authenticat
ion.                                                                                                                                
Aug 29, 2018 21:27:11.852 [0x80af4d100] VERBOSE - Auth: Came in with the master token, authorization succeeded.                     
Aug 29, 2018 21:27:11.852 [0x80e251500] DEBUG - Request: [127.0.0.1:24310 (Loopback)] GET /:/metadata/updateProgressMessage?message=
Scanning%20Dan%20Carlin%20-%20Hardcore%20History (9 live) GZIP Signed-in Token (parski)                                             
Aug 29, 2018 21:27:11.852 [0x80e251500] VERBOSE -  * User-Agent => Mozilla/5.0 (Windows NT 10.0; WOW64) AppleWebKit/537.36 (KHTML, l
ike Gecko) Chrome/47.0.2526.106 Safari/537.36                                                                                       
Aug 29, 2018 21:27:11.852 [0x80e251500] VERBOSE -  * Host => 127.0.0.1:32400                                                        
Aug 29, 2018 21:27:11.852 [0x80e251500] VERBOSE -  * Accept => */*                                                                  
Aug 29, 2018 21:27:11.852 [0x80e251500] VERBOSE -  * Accept-Encoding => gzip                                                        
Aug 29, 2018 21:27:11.852 [0x80e251500] VERBOSE -  * X-Plex-Token => xxxxxxxxxxxxxxxxxxxx                                           
Aug 29, 2018 21:27:11.852 [0x80e251500] VERBOSE -  * message => Scanning Dan Carlin - Hardcore History                              
Aug 29, 2018 21:27:11.852 [0x80af4d100] DEBUG - Completed: [127.0.0.1:24310] 200 GET /:/metadata/updateProgressMessage?message=Scann
ing%20Dan%20Carlin%20-%20Hardcore%20History (9 live) GZIP 0ms 166 bytes                                                             
Aug 29, 2018 21:27:11.862 [0x80b3dac00] VERBOSE - JobManager: child process with PID 94769 exited                                   
Aug 29, 2018 21:27:11.862 [0x80b3dac00] DEBUG - Jobs: '/usr/local/share/plexmediaserver/Plex Media Scanner' exit code for process 94
769 is 0 (success)                                                                                                                  
Aug 29, 2018 21:27:11.864 [0x80e252900] DEBUG - Activity: registered new activity c5c4062b-5404-4408-8879-78e7c52987b6 - Processing 
subscriptions                                                                                                                       
Aug 29, 2018 21:27:11.864 [0x80e252900] DEBUG - Scanning section 11                                                                 
Aug 29, 2018 21:27:11.864 [0x80e252900] DEBUG - Killing job.                                                                        
Aug 29, 2018 21:27:11.864 [0x80e252900] DEBUG - Signalling job ID 94769 with 9                                                      
Aug 29, 2018 21:27:11.864 [0x80e252900] DEBUG - Job running: EAE_ROOT='/tmp/pms-3e68ea52-e03a-4b4a-bab3-61c116f7a1e8/EasyAudioEncode
r' FFMPEG_EXTERNAL_LIBS='/usr/local/plexdata/Plex\ Media\ Server/Codecs/e944d3a-1309-freebsd-x86_64/' X_PLEX_TOKEN='xxxxxxxxxxxxxxxx
xxxx' '/usr/local/share/plexmediaserver/Plex Media Scanner' '--scan' '--refresh' '--section' '11'
7

I would need to look at the whole log files zip taken after restart following a crash

That would allow me to see how the various processes are hanging together and also if we do have crashes and crash reporting is enabled, to see if the crash reports got uploaded and what identifiers they had

And would like to see the start up sequence in the logs

See
https://support.plex.tv/articles/201643703-reporting-issues-with-plex-media-server/
https://support.plex.tv/articles/200250417-plex-media-server-log-files/

With regards to the error on 127.0.0.1 - there have been cases of users not having a loopback interface defined in a FreeNAS jail setup.

There were several old forum topics with problems caused by missing localhost interface in the configuration

8

It crashed again and this time I created an archive of all the logs when Plex was in a crashed state as well as after restarting the jail.

Crashed state:
crashed_logs.zip (3.6 MB)

After restart:
restart_logs.zip (3.2 MB)

9

Thanks for the logs. The server does appear to have crashed out sometime after Sep 09, 2018 11:59:44… There are no clues in the log as to why it would crash. The last logged activity was to start a scanner process which did run ok until the server crashed and it no longer could communicate with the server process.

Unfortunately there is currently no crash reporting for FreeBSD platform and the only suggestion I have is to make sure you are always on the latest version of Plex Media Server with fixes for crashes identified from crash reports from other platforms

The latest beta is version 1.13.8.5395

10

I’ve had the same exact problem for the past couple of months running FreeBSD 11.2 and always the latest version of Plex Media Server, currently 1.13.9.5439. The issue is always triggered by someone simply browsing my collection for something to watch. I’ve now created a watchdog script to monitor/restart the Plex_Media_Server process every minute, but it’s gotten to the point that some users have given up on trying to even use it as it crashes so often.

11

Thank you for sharing. I’m sorry you’re also having problems but I’m glad I’m not alone with this issue. Please let me know if you are able to solve the problem somehow and I will of course do the same.

I can also confirm that the latest version is still crashing.

12

No harm in getting more log files of crashes and if easily repeatable, would not mind one set with verbose+debug logging - in case of extra clues

Of course any pattern you get to establish for steps to cause the crash would help as well

13

Plex started to crash for me on FreeBSD around July so over the weekend I downgraded to the last June release, 1.13.2.5154, and it hasn’t crashed since. I’ll give it a few more days before updating to a newer release to try and isolate which version introduced the instability on FreeBSD.

14

That’s an excellent idea! I’ve also reverted to 1.13.2.5154. I’ll let it run for now to see what happens.

15

I got a message from one of my users yesterday saying that he crashed my Plex. I haven’t had time to look at it until now but this time it’s looking different so it might be another issue altogether.

Looking at ps ax I can see the Plex Media Server process (PID 73375) running:

  PID TT  STAT    TIME COMMAND
73309  -  SsJ  0:00.41 /usr/sbin/syslogd -s
73375  -  IsJ  2:25.78 /usr/local/share/plexmediaserver/Plex_Media_Server (Plex Media Server)
73390  -  IsJ  0:00.81 /usr/sbin/cron -s
73445  -  INJ  1:19.94 Plex Plug-in [com.plexapp.system] /usr/local/share/plexmediaserver/Resources/Plug-ins-fd05be322/Framework.bundle/Contents/Resources/Versions/2/Python/bootstrap.py --server-version 1.13.2.5154-fd05be322 /usr/
73471  -  IJ   2:48.99 /usr/local/share/plexmediaserver/Plex DLNA Server
73472  -  IJ   0:04.00 /usr/local/share/plexmediaserver/Plex Tuner Service /usr/local/share/plexmediaserver/Resources/Tuner/Private /usr/local/share/plexmediaserver/Resources/Tuner/Shared 1.13.2.5154-fd05be322 32600 /waitmutex
73473  -  IJ   2:05.83 Plex Plug-in [com.plexapp.agents.subzero] /usr/local/share/plexmediaserver/Resources/Plug-ins-fd05be322/Framework.bundle/Contents/Resources/Versions/2/Python/bootstrap.py --server-version 1.13.2.5154-fd05be3
75568  -  IJ   0:00.00 /bin/sh /etc/periodic/daily/480.leapfile-ntpd
75571  -  IJ   0:00.00 sleep 81155
37988  0  SJ   0:00.01 sh

I can’t access Plex via the web interface. I’m not sure how to interpret it. Here is an exerpt from Plex Media Server.log:

Oct 24, 2018 18:01:01.690 [0x80c848400] DEBUG - Content-Length of /usr/local/plexdata/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-lp7h7nohbnhmiroakcg5nf6i-fc0f48de-e5e9-402a-99a6-d51f77c56590/init-stream0.m4s,/usr/local/plexdata/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-lp7h7nohbnhmiroakcg5nf6i-fc0f48de-e5e9-402a-99a6-d51f77c56590/chunk-stream0-00013.m4s is 1678142.
Oct 24, 2018 18:01:01.837 [0x80ad4c100] DEBUG - Completed: [37.247.1.221:50100] 200 GET /video/:/transcode/universal/dash/lp7h7nohbnhmiroakcg5nf6i/0/12.m4s (12 live) TLS GZIP 146ms 1678142 bytes (pipelined: 95)
Oct 24, 2018 18:01:01.908 [0x80c848400] DEBUG - Session lp7h7nohbnhmiroakcg5nf6i (4) is throttling
Oct 24, 2018 18:01:01.908 [0x80be2b900] DEBUG - [Transcoder] Throttle - Going into sloth mode.
Oct 24, 2018 18:01:02.063 [0x80c848400] DEBUG - Request: [37.247.1.221:50100 (WAN)] GET /video/:/transcode/universal/dash/lp7h7nohbnhmiroakcg5nf6i/0/13.m4s (12 live) TLS GZIP Signed-in
Oct 24, 2018 18:01:02.063 [0x80c848400] DEBUG - Asked for segment 13 from session.
Oct 24, 2018 18:01:02.063 [0x80c848400] DEBUG - Returning segment 13 from session: "/usr/local/plexdata/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-lp7h7nohbnhmiroakcg5nf6i-fc0f48de-e5e9-402a-99a6-d51f77c56590/chunk-stream0-00014.m4s"
Oct 24, 2018 18:01:02.063 [0x80c848400] DEBUG - Content-Length of /usr/local/plexdata/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-lp7h7nohbnhmiroakcg5nf6i-fc0f48de-e5e9-402a-99a6-d51f77c56590/init-stream0.m4s,/usr/local/plexdata/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-lp7h7nohbnhmiroakcg5nf6i-fc0f48de-e5e9-402a-99a6-d51f77c56590/chunk-stream0-00014.m4s is 2470577.
Oct 24, 2018 18:01:02.278 [0x80ad4c600] DEBUG - Completed: [37.247.1.221:50100] 200 GET /video/:/transcode/universal/dash/lp7h7nohbnhmiroakcg5nf6i/0/13.m4s (12 live) TLS GZIP 215ms 2470577 bytes (pipelined: 96)
Oct 24, 2018 18:01:02.319 [0x80c848400] DEBUG - Request: [37.247.1.221:50100 (WAN)] GET /video/:/transcode/universal/dash/lp7h7nohbnhmiroakcg5nf6i/0/14.m4s (12 live) TLS GZIP Signed-in
Oct 24, 2018 18:01:02.319 [0x80c848400] DEBUG - Asked for segment 14 from session.
Oct 24, 2018 18:01:02.319 [0x80c848400] DEBUG - Returning segment 14 from session: "/usr/local/plexdata/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-lp7h7nohbnhmiroakcg5nf6i-fc0f48de-e5e9-402a-99a6-d51f77c56590/chunk-stream0-00015.m4s"
Oct 24, 2018 18:01:02.319 [0x80c848400] DEBUG - Content-Length of /usr/local/plexdata/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-lp7h7nohbnhmiroakcg5nf6i-fc0f48de-e5e9-402a-99a6-d51f77c56590/init-stream0.m4s,/usr/local/plexdata/Plex Media Server/Cache/Transcode/Sessions/plex-transcode-lp7h7nohbnhmiroakcg5nf6i-fc0f48de-e5e9-402a-99a6-d51f77c56590/chunk-stream0-00015.m4s is 3135170.
Oct 24, 2018 18:01:02.551 [0x80dc73000] DEBUG - Session lp7h7nohbnhmiroakcg5nf6i (4) is unthrottling
Oct 24, 2018 18:01:02.552 [0x80be2b900] DEBUG - [Transcoder] Throttle - Getting back to work.
Oct 24, 2018 18:01:02.657 [0x80dc73000] DEBUG - Transcoder segment range: 0 - 21
Oct 24, 2018 18:01:02.880 [0x80ad4c600] DEBUG - Completed: [37.247.1.221:50100] 200 GET /video/:/transcode/universal/dash/lp7h7nohbnhmiroakcg5nf6i/0/14.m4s (13 live) TLS GZIP 561ms 3135170 bytes (pipelined: 97)
Oct 24, 2018 18:01:02.947 [0x80dc73000] DEBUG - Session lp7h7nohbnhmiroakcg5nf6i (4) is throttling
Oct 24, 2018 18:01:02.948 [0x80be2b900] DEBUG - [Transcoder] Throttle - Going into sloth mode.
Oct 24, 2018 18:01:03.650 [0x80be2b900] DEBUG - Request: [37.247.1.221:50100 (WAN)] GET /video/:/transcode/universal/dash/lp7h7nohbnhmiroakcg5nf6i/1/608.m4s (12 live) TLS GZIP Signed-in
Oct 24, 2018 18:01:03.650 [0x80be2b900] DEBUG - Asked for segment 608 from session.
Oct 24, 2018 18:01:03.650 [0x80be2b900] DEBUG - We're in a seek: asked for 608, min/max available was 0/21
Oct 24, 2018 18:01:03.650 [0x80be2b900] DEBUG - Segment #608 WON.
Oct 24, 2018 18:01:03.650 [0x80be2b900] DEBUG - Killing job.
Oct 24, 2018 18:01:03.650 [0x80be2b900] DEBUG - Signalling job ID 44504 with 9
Oct 24, 2018 18:01:03.650 [0x80dc73a00] DEBUG - Request: [37.247.1.221:50103 (WAN)] GET /video/:/transcode/universal/dash/lp7h7nohbnhmiroakcg5nf6i/0/608.m4s (12 live) TLS GZIP Signed-in
Oct 24, 2018 18:01:03.650 [0x80be2b900] DEBUG - Job was already killed, not killing again.
Oct 24, 2018 18:01:03.650 [0x80be2b900] DEBUG - Stopping transcode session lp7h7nohbnhmiroakcg5nf6i
Oct 24, 2018 18:01:03.650 [0x80dc73a00] DEBUG - Asked for segment 608 from session.
Oct 24, 2018 18:01:03.652 [0x80be2b900] DEBUG - Starting a transcode session lp7h7nohbnhmiroakcg5nf6i at offset 3040.0 (state=3)
Oct 24, 2018 18:01:03.654 [0x80be2b900] DEBUG - [Universal] Using local file path instead of URL: /mnt/pool/Movies/Eighth Grade (2018)/Eighth Grade (2018).mkv
Oct 24, 2018 18:01:03.655 [0x80be2b900] DEBUG - Job running: EAE_ROOT='/tmp/pms-5247d7c4-e1cd-4245-b3b6-15613f7120c0/EasyAudioEncoder' FFMPEG_EXTERNAL_LIBS='/usr/local/plexdata/Plex\ Media\ Server/Codecs/e2b7800-1302-freebsd-x86_64/' XDG_CACHE_HOME='/usr/local/plexdata/Plex Media Server/Cache/' XDG_DATA_HOME='/usr/local/share/plexmediaserver/Resources/' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' '/usr/local/share/plexmediaserver/Plex Transcoder' '-codec:0' 'h264' '-codec:1' 'dca' '-ss' '3040' '-noaccurate_seek' '-i' '/mnt/pool/Movies/Eighth Grade (2018)/Eighth Grade (2018).mkv' '-filter_complex' '[0:1] aresample=async=1:ocl='\''stereo'\'':osr=48000[0]' '-map' '0:0' '-metadata:s:0' 'language=eng' '-codec:0' 'copy' '-map' '[0]' '-metadata:s:1' 'language=eng' '-codec:1' 'aac' '-b:1' '256k' '-f' 'dash' '-min_seg_duration' '5000000' '-skip_to_segment' '609' '-time_delta' '0.0625' '-manifest_name' 'http://127.0.0.1:32400/video/:/transcode/session/lp7h7nohbnhmiroakcg5nf6i/4d75e547-c672-4cd5-b49b-c24af3cbc84f/manifest' '-avoid_negative_ts' 'disabled' '-map_metadata' '-1' '-map_chapters' '-1' 'dash' '-start_at_zero' '-copyts' '-y' '-nostats' '-loglevel' 'quiet' '-loglevel_plex' 'error' '-progressurl' 'http://127.0.0.1:32400/video/:/transcode/session/lp7h7nohbnhmiroakcg5nf6i/4d75e547-c672-4cd5-b49b-c24af3cbc84f/progress'
Oct 24, 2018 18:01:03.668 [0x80b1ef700] DEBUG - Jobs: '/usr/local/share/plexmediaserver/Plex Transcoder' exit code for process 44504 is -9 (signal: Killed)
Oct 24, 2018 18:01:03.668 [0x80be2b900] DEBUG - Jobs: Starting child process with pid 44516
Oct 24, 2018 18:01:03.669 [0x80be2b900] DEBUG - Started session successfully: lp7h7nohbnhmiroakcg5nf6i
Oct 24, 2018 18:01:03.670 [0x80b1ee800] DEBUG - Streaming Resource: Resetting play progress due to seek
Oct 24, 2018 18:01:44.802 [0x80b1ed400] DEBUG - BPQ: deferring onLibraryChanged callback, only 49 seconds since last library change
Oct 24, 2018 18:01:55.814 [0x80da50b00] DEBUG - BPQ: onConsiderProcessing: Idle (true)
Oct 24, 2018 18:01:55.814 [0x80da50b00] DEBUG - BPQ: [Idle] -> [Processing]
Oct 24, 2018 18:01:55.816 [0x80da50b00] DEBUG - BPQ: generating queue items from 9 generator(s)
Oct 24, 2018 18:01:55.817 [0x80da50b00] DEBUG - Sync: skipping sync list 26573127 from device Mats nya fina iPad because it's snoozing
Oct 24, 2018 18:01:55.817 [0x80da50b00] DEBUG - Sync: updating status for sync list 26573127, sync item 28619060, generator 114
Oct 24, 2018 18:01:55.820 [0x80da50b00] DEBUG - Sync: skipping sync list 26573127 from device Mats nya fina iPad because it's snoozing
Oct 24, 2018 18:01:55.820 [0x80da50b00] DEBUG - Sync: updating status for sync list 26573127, sync item 29893743, generator 444
Oct 24, 2018 18:01:55.823 [0x80da50b00] DEBUG - Sync: skipping sync list 26573127 from device Mats nya fina iPad because it's snoozing
Oct 24, 2018 18:01:55.823 [0x80da50b00] DEBUG - Sync: updating status for sync list 26573127, sync item 29893846, generator 447
Oct 24, 2018 18:01:55.825 [0x80da50b00] DEBUG - Sync: skipping sync list 26573127 from device Mats nya fina iPad because it's snoozing
Oct 24, 2018 18:01:55.825 [0x80da50b00] DEBUG - Sync: updating status for sync list 26573127, sync item 30052114, generator 475
Oct 24, 2018 18:01:55.828 [0x80da50b00] DEBUG - Sync: skipping sync list 26573127 from device Mats nya fina iPad because it's snoozing
Oct 24, 2018 18:01:55.828 [0x80da50b00] DEBUG - Sync: updating status for sync list 26573127, sync item 30400532, generator 528
Oct 24, 2018 18:01:55.831 [0x80da50b00] DEBUG - Sync: skipping sync list 21141338 from device Erykah because it's snoozing
Oct 24, 2018 18:01:55.831 [0x80da50b00] DEBUG - Sync: updating status for sync list 21141338, sync item 29514129, generator 333
Oct 24, 2018 18:01:55.834 [0x80da50b00] DEBUG - Sync: skipping sync list 21141338 from device Erykah because it's snoozing
Oct 24, 2018 18:01:55.834 [0x80da50b00] DEBUG - Sync: updating status for sync list 21141338, sync item 29514133, generator 334
Oct 24, 2018 18:01:55.837 [0x80da50b00] DEBUG - Sync: skipping sync list 21141338 from device Erykah because it's snoozing
Oct 24, 2018 18:01:55.837 [0x80da50b00] DEBUG - Sync: updating status for sync list 21141338, sync item 29514147, generator 335
Oct 24, 2018 18:01:55.840 [0x80da50b00] DEBUG - Sync: skipping sync list 21141338 from device Erykah because it's snoozing
Oct 24, 2018 18:01:55.840 [0x80da50b00] DEBUG - Sync: updating status for sync list 21141338, sync item 29514160, generator 336
Oct 24, 2018 18:01:55.846 [0x80da50b00] DEBUG - BPQ: generated 0 item(s) for queue
Oct 24, 2018 18:01:55.846 [0x80da50b00] DEBUG - PlayQueue: 0 generated IDs compressed down to a 2 byte blob.
Oct 24, 2018 18:01:55.846 [0x80da50b00] DEBUG - PlayQueue: 0 generated IDs compressed down to a 2 byte blob.
Oct 24, 2018 18:03:11.812 [0x80be2b900] WARN - Timed out waiting for segment.
Oct 24, 2018 18:03:12.025 [0x80dc73a00] WARN - Timed out waiting for segment.
Oct 24, 2018 18:04:04.391 [0x80b1f0100] DEBUG - Shutting down idle session lp7h7nohbnhmiroakcg5nf6i (idle time is 180 seconds)
Oct 24, 2018 18:04:04.391 [0x80b1f0100] DEBUG - Killing job.
Oct 24, 2018 18:04:04.391 [0x80b1f0100] DEBUG - Signalling job ID 44516 with 9
Oct 24, 2018 18:04:04.391 [0x80b1f0100] DEBUG - Job was already killed, not killing again.
Oct 24, 2018 18:04:04.391 [0x80b1f0100] DEBUG - Stopping transcode session lp7h7nohbnhmiroakcg5nf6i
Oct 24, 2018 18:04:04.392 [0x80b1ef700] DEBUG - Jobs: '/usr/local/share/plexmediaserver/Plex Transcoder' exit code for process 44516 is -9 (signal: Killed)
Oct 24, 2018 18:04:15.007 [0x80ad4b200] DEBUG - Streaming Resource: Timing out session 0x80f6d07a0:3v2ia9wfjsbsj7r139kg4o59
Oct 24, 2018 18:04:15.007 [0x80ad4b200] DEBUG - Streaming Resource: Terminating session 0x80f6d07a0:3v2ia9wfjsbsj7r139kg4o59 which is using 6872kbps of WAN bandwidth.  Used is now 0kbps
Oct 24, 2018 18:04:15.007 [0x80ad4b200] DEBUG - Streaming Resource: Terminated session 0x80f6d07a0:3v2ia9wfjsbsj7r139kg4o59 with reason Client stopped playback.
Oct 24, 2018 18:04:15.007 [0x80ad4b200] DEBUG - Streaming Resource: Removing session 0x80f6d07a0:3v2ia9wfjsbsj7r139kg4o59
Oct 24, 2018 18:04:15.007 [0x812c2aa00] DEBUG - Job was already killed, not killing again.
Oct 24, 2018 18:04:15.007 [0x812c2aa00] DEBUG - Job was already killed, not killing again.
Oct 24, 2018 18:29:13.987 [0x80b1ede00] DEBUG - PublicAddressManager: Obtaining public address and mapping port.
Oct 24, 2018 18:29:16.832 [0x80b62f300] DEBUG - Sync: uploadStatus
Oct 24, 2018 18:59:16.873 [0x80dcc9900] DEBUG - Sync: uploadStatus
Oct 24, 2018 19:00:03.804 [0x80dbb0000] DEBUG - Statistics: Flushing 2 expired bandwidth entries, 1 expired media entries.
Oct 24, 2018 19:29:16.895 [0x80dcc8f00] DEBUG - Sync: uploadStatus
Oct 24, 2018 19:59:16.937 [0x80b1ed900] DEBUG - Sync: uploadStatus
Oct 24, 2018 20:29:17.000 [0x80b1f0600] DEBUG - Sync: uploadStatus
Oct 24, 2018 20:59:17.140 [0x80b1eed00] DEBUG - Sync: uploadStatus
Oct 24, 2018 21:29:09.965 [0x80cf63300] DEBUG - HTTP requesting GET http://ocspx.digicert.com/MFEwTzBNMEswSTAJBgUrDgMCGgUABBSnVdbEyh8T3xvVlkPGHNCJxnqCPgQUlIuJ90hyifJRStmIe%2BVhtaqc1QECEAdJiDFWN5HxT7r6Ttt%2Fy0s%3D
Oct 24, 2018 21:29:10.013 [0x80cf63300] DEBUG - HTTP 200 response from GET http://ocspx.digicert.com/MFEwTzBNMEswSTAJBgUrDgMCGgUABBSnVdbEyh8T3xvVlkPGHNCJxnqCPgQUlIuJ90hyifJRStmIe%2BVhtaqc1QECEAdJiDFWN5HxT7r6Ttt%2Fy0s%3D
Oct 24, 2018 21:29:10.014 [0x80cf63300] INFO - OCSP: Successfully retrieved response.
Oct 24, 2018 21:29:17.180 [0x80ad4b200] DEBUG - Sync: uploadStatus
Oct 24, 2018 21:59:17.254 [0x80dc74900] DEBUG - Sync: uploadStatus
Oct 24, 2018 22:29:17.255 [0x80b1ee800] DEBUG - Sync: uploadStatus
Oct 24, 2018 22:59:17.256 [0x80da4cf00] DEBUG - Sync: uploadStatus
Oct 24, 2018 23:29:17.431 [0x80b1ee300] DEBUG - Sync: uploadStatus
Oct 24, 2018 23:59:17.498 [0x80b1ed400] DEBUG - Sync: uploadStatus
Oct 25, 2018 00:00:02.510 [0x80b1ee300] DEBUG - Statistics: Flushing 6 expired bandwidth entries, 2 expired media entries.
Oct 25, 2018 00:29:17.543 [0x80b1ee300] DEBUG - Sync: uploadStatus
Oct 25, 2018 00:59:17.874 [0x80dbb0000] DEBUG - Sync: uploadStatus
Oct 25, 2018 01:29:17.892 [0x80c848400] DEBUG - Sync: uploadStatus
Oct 25, 2018 01:59:17.899 [0x80dcc9900] DEBUG - Sync: uploadStatus
Oct 25, 2018 02:29:18.134 [0x80dbb0000] DEBUG - Sync: uploadStatus
Oct 25, 2018 02:59:18.136 [0x80dc74900] DEBUG - Sync: uploadStatus
Oct 25, 2018 03:29:13.021 [0x80c848400] DEBUG - HubCache: Purging 8 hubs for not being accessed in 24 hours.
Oct 25, 2018 03:29:18.202 [0x80c848400] DEBUG - Sync: uploadStatus
Oct 25, 2018 03:59:18.227 [0x80c848400] DEBUG - Sync: uploadStatus
Oct 25, 2018 04:29:18.274 [0x80b1ee800] DEBUG - Sync: uploadStatus
Oct 25, 2018 04:59:18.276 [0x80dcc9900] DEBUG - Sync: uploadStatus
Oct 25, 2018 05:29:18.337 [0x80b1ed400] DEBUG - Sync: uploadStatus
Oct 25, 2018 05:59:18.708 [0x80b1ed400] DEBUG - Sync: uploadStatus
Oct 25, 2018 06:29:18.766 [0x80dbb0000] DEBUG - Sync: uploadStatus
Oct 25, 2018 06:59:18.768 [0x80dc74900] DEBUG - Sync: uploadStatus
Oct 25, 2018 07:29:18.798 [0x80c848400] DEBUG - Sync: uploadStatus
Oct 25, 2018 07:59:18.893 [0x80b1ee800] DEBUG - Sync: uploadStatus
Oct 25, 2018 08:29:19.069 [0x80ad4b200] DEBUG - Sync: uploadStatus
Oct 25, 2018 08:59:19.133 [0x80cf63300] DEBUG - Sync: uploadStatus
Oct 25, 2018 09:29:19.165 [0x80b1ed900] DEBUG - Sync: uploadStatus
Oct 25, 2018 09:59:19.173 [0x80b1ee800] DEBUG - Sync: uploadStatus
Oct 25, 2018 10:29:19.328 [0x80dc74900] DEBUG - Sync: uploadStatus
Oct 25, 2018 10:59:19.786 [0x80dcc9900] DEBUG - Sync: uploadStatus
Oct 25, 2018 11:29:19.934 [0x80b1ee300] DEBUG - Sync: uploadStatus
Oct 25, 2018 11:59:19.994 [0x80b1ed400] DEBUG - Sync: uploadStatus
Oct 25, 2018 12:29:20.022 [0x80dbb0000] DEBUG - Sync: uploadStatus
Oct 25, 2018 12:59:20.086 [0x80dcc9900] DEBUG - Sync: uploadStatus
Oct 25, 2018 13:29:20.362 [0x80c848400] DEBUG - Sync: uploadStatus
Oct 25, 2018 13:59:20.367 [0x80cf63300] DEBUG - Sync: uploadStatus
Oct 25, 2018 14:29:20.369 [0x80dc74900] DEBUG - Sync: uploadStatus
Oct 25, 2018 14:59:20.434 [0x80c848400] DEBUG - Sync: uploadStatus
Oct 25, 2018 15:29:20.446 [0x80b1ee300] DEBUG - Sync: uploadStatus
Oct 25, 2018 15:59:20.453 [0x80b1ed900] DEBUG - Sync: uploadStatus
Oct 25, 2018 16:29:20.498 [0x80b1ed900] DEBUG - Sync: uploadStatus
Oct 25, 2018 16:59:20.538 [0x80cf63300] DEBUG - Sync: uploadStatus
Oct 25, 2018 17:29:20.591 [0x80b1ee300] DEBUG - Sync: uploadStatus
Oct 25, 2018 17:59:20.610 [0x80cf63300] DEBUG - Sync: uploadStatus
Oct 25, 2018 18:29:20.633 [0x80dbb0000] DEBUG - Sync: uploadStatus
Oct 25, 2018 18:59:20.642 [0x80ad4b200] DEBUG - Sync: uploadStatus
Oct 25, 2018 19:29:20.686 [0x80dcc9900] DEBUG - Sync: uploadStatus
Oct 25, 2018 19:59:25.547 [0x80b1ee800] DEBUG - Sync: uploadStatus
Oct 25, 2018 20:29:25.581 [0x80dcc9900] DEBUG - Sync: uploadStatus
Oct 25, 2018 20:59:25.670 [0x80dc74900] DEBUG - Sync: uploadStatus
Oct 25, 2018 21:29:10.063 [0x80dbb0000] DEBUG - HTTP requesting GET http://ocspx.digicert.com/MFEwTzBNMEswSTAJBgUrDgMCGgUABBSnVdbEyh8T3xvVlkPGHNCJxnqCPgQUlIuJ90hyifJRStmIe%2BVhtaqc1QECEAdJiDFWN5HxT7r6Ttt%2Fy0s%3D
Oct 25, 2018 21:29:10.092 [0x80dbb0000] DEBUG - HTTP 200 response from GET http://ocspx.digicert.com/MFEwTzBNMEswSTAJBgUrDgMCGgUABBSnVdbEyh8T3xvVlkPGHNCJxnqCPgQUlIuJ90hyifJRStmIe%2BVhtaqc1QECEAdJiDFWN5HxT7r6Ttt%2Fy0s%3D
Oct 25, 2018 21:29:10.092 [0x80dbb0000] INFO - OCSP: Successfully retrieved response.
Oct 25, 2018 21:29:12.388 [0x80b1ee300] DEBUG - Downloading document http://127.0.0.1:32400/:/plugins/com.plexapp.agents.imdb/prefs
Oct 25, 2018 21:29:13.239 [0x80dbb0000] DEBUG - HubCache: Purging 43 hubs for not being accessed in 24 hours.
Oct 25, 2018 21:29:25.700 [0x80b1ed900] DEBUG - Sync: uploadStatus
Oct 25, 2018 21:59:25.969 [0x80b1ee800] DEBUG - Sync: uploadStatus
Oct 25, 2018 22:29:26.009 [0x80c848400] DEBUG - Sync: uploadStatus
Oct 25, 2018 22:59:26.028 [0x80da4cf00] DEBUG - Sync: uploadStatus

My friend said he scrobbled to some time in the middle of the video and that’s when the crash occurred.

I’ve attached the logs if they are of any use but again, this seems to be a different crash.

logs.zip (2.6 MB)

Still on version 1.13.2.5154 as of right now.

16

PMS appears to have deadlocked just after 18:01:03

Unfortunately for deadlocks investigation one needs a process dump - but there isn’t any crash reports handling on FreeBSD - so we can’t get the standard deadlock diagnostics when they occur on this platform

Looking at the release notes post 1.13.2.5154 there were fixes for 2 deadlocks in release 1.13.4.5251

  • (Playback) Rare deadlock with stopping sessions (#8659)
  • (Streaming Brain) Rare deadlock involving bandwidth limits (#8498)

I cannot say if the deadlock would be fixed by these changes

17

I only had a single crash in a week with 1.13.2.5154, which is far better than before as it was crashing multiple times a day with the latest releases. I did go ahead and upgrade to 1.13.4.5251 for further testing, but the date of this release is approx. when my issues started.

18

No crashes since the deadlock on version 1.13.2.5154. Feels sort of bad to be stuck on an old version but it’s well worth it for it not crashing.

19

My crashes returned when upgrading from 1.13.2.5154 to 1.13.4.5251, so whatever changes were made between these two releases introduced the constant crashing on FreeBSD.

20

Hopefully they are not unique to FreeBSD and they will get fixed when the crashes are reported from other platforms.