Freenas 11.2-u3 getting "exited on signal 10"

Plex Media Server NAS & Devices
1

Server Version#: 1.15.4.919
Player Version#: 3.97.3

If I didnt scrub everything I need to from my log below, please tell me. Overall I have recently been getting signal 10 exits on FreeNAS. Not sure if it is some plex related issue. Based on the look of it, it seems it occured when a user tried playing something on a chromecast. My system can handle a few transcodes. At the time this happened, there was no one else playing anything anyway.

Apr 26, 2019 05:17:23.949 [0x80c862300] DEBUG - Completed: [USERIPADDRESS:41735] 200 OPTIONS /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=1705&playQueueItemID=565889&state=playing&hasMDE=1&time=67000&duration=5458000 (19 live) TLS GZIP 0ms 598 bytes (pipelined: 1)
Apr 26, 2019 05:17:24.118 [0x80c862300] DEBUG - Auth: authenticated user 4877713 as User11111
Apr 26, 2019 05:17:24.119 [0x80daef500] DEBUG - Request: [USERIPADDRESS:41730 (WAN)] GET /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=985&playQueueItemID=565889&state=playing&hasMDE=1&time=67000&duration=5458000 (19 live) TLS GZIP Signed-in Token (User11111)
Apr 26, 2019 05:17:24.120 [0x80daef500] DEBUG - Client [j9ala9p21nsk7etqnmqodvhy] reporting timeline state playing, progress of 67000/5458000ms for guid=, ratingKey=221583 url=, key=/library/metadata/221583, containerKey=, metadataId=221583, source=
Apr 26, 2019 05:17:24.146 [0x80daef500] DEBUG - Play progress on 221583 'Minions' - got played 67000 ms by account 4877713!
Apr 26, 2019 05:17:24.146 [0x80daef500] DEBUG - [Now] User is User11111 (ID: 4877713)
Apr 26, 2019 05:17:24.146 [0x80daef500] DEBUG - [Now] Device is Chromecast (Chromecast).
Apr 26, 2019 05:17:24.146 [0x80daef500] DEBUG - [Now] Profile is Chromecast
Apr 26, 2019 05:17:24.146 [0x80daef500] DEBUG - [Now] Updated play state for /library/metadata/221583.
Apr 26, 2019 05:17:24.147 [0x80daef500] DEBUG - Statistics: (thyuawiy1kgpbno6rw1voa2q) Reporting active playback in state 0 of type 1 (scrobble: 0) for account 4877713
Apr 26, 2019 05:17:24.150 [0x80c862300] DEBUG - Completed: [USERIPADDRESS:41730] 200 GET /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=985&playQueueItemID=565889&state=playing&hasMDE=1&time=67000&duration=5458000 (18 live) TLS GZIP 30ms 572 bytes (pipelined: 6)
Apr 26, 2019 05:17:24.327 [0x80c862800] DEBUG - Auth: authenticated user 4877713 as User11111
Apr 26, 2019 05:17:24.328 [0x80cccb900] DEBUG - Request: [USERIPADDRESS:41733 (WAN)] GET /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=985&playQueueItemID=565889&state=buffering&hasMDE=1&time=67000&duration=5458000 (17 live) TLS GZIP Signed-in Token (User11111)
Apr 26, 2019 05:17:24.329 [0x80cccb900] DEBUG - Client [j9ala9p21nsk7etqnmqodvhy] reporting timeline state buffering, progress of 67000/5458000ms for guid=, ratingKey=221583 url=, key=/library/metadata/221583, containerKey=, metadataId=221583, source=
Apr 26, 2019 05:17:24.360 [0x80cccb900] DEBUG - Play progress on 221583 'Minions' - got played 67000 ms by account 4877713!
Apr 26, 2019 05:17:24.360 [0x80cccb900] DEBUG - [Now] User is User11111 (ID: 4877713)
Apr 26, 2019 05:17:24.360 [0x80cccb900] DEBUG - [Now] Device is Chromecast (Chromecast).
Apr 26, 2019 05:17:24.360 [0x80cccb900] DEBUG - [Now] Profile is Chromecast
Apr 26, 2019 05:17:24.360 [0x80cccb900] DEBUG - [Now] Updated play state for /library/metadata/221583.
Apr 26, 2019 05:17:24.360 [0x80cccb900] DEBUG - Statistics: (thyuawiy1kgpbno6rw1voa2q) Reporting active playback in state 2 of type 1 (scrobble: 0) for account 4877713
Apr 26, 2019 05:17:24.363 [0x80c862800] DEBUG - Completed: [USERIPADDRESS:41733] 200 GET /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=985&playQueueItemID=565889&state=buffering&hasMDE=1&time=67000&duration=5458000 (17 live) TLS GZIP 35ms 572 bytes (pipelined: 3)
Apr 26, 2019 05:17:24.480 [0x80c862800] DEBUG - Auth: authenticated user 4877713 as User11111
Apr 26, 2019 05:17:24.481 [0x80daef500] DEBUG - Request: [USERIPADDRESS:41730 (WAN)] GET /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=1705&playQueueItemID=565889&state=playing&hasMDE=1&time=67000&duration=5458000 (18 live) TLS GZIP Signed-in Token (User11111)
Apr 26, 2019 05:17:24.481 [0x80daef500] DEBUG - Client [j9ala9p21nsk7etqnmqodvhy] reporting timeline state playing, progress of 67000/5458000ms for guid=, ratingKey=221583 url=, key=/library/metadata/221583, containerKey=, metadataId=221583, source=
Apr 26, 2019 05:17:24.515 [0x80daef500] DEBUG - Play progress on 221583 'Minions' - got played 67000 ms by account 4877713!
Apr 26, 2019 05:17:24.515 [0x80daef500] DEBUG - [Now] User is User11111 (ID: 4877713)
Apr 26, 2019 05:17:24.515 [0x80daef500] DEBUG - [Now] Device is Chromecast (Chromecast).
Apr 26, 2019 05:17:24.515 [0x80daef500] DEBUG - [Now] Profile is Chromecast
Apr 26, 2019 05:17:24.515 [0x80daef500] DEBUG - [Now] Updated play state for /library/metadata/221583.
Apr 26, 2019 05:17:24.515 [0x80daef500] DEBUG - Statistics: (thyuawiy1kgpbno6rw1voa2q) Reporting active playback in state 0 of type 1 (scrobble: 0) for account 4877713
Apr 26, 2019 05:17:24.517 [0x80c862800] DEBUG - Completed: [USERIPADDRESS:41730] 200 GET /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=1705&playQueueItemID=565889&state=playing&hasMDE=1&time=67000&duration=5458000 (20 live) TLS GZIP 36ms 572 bytes (pipelined: 7)
Apr 26, 2019 05:17:24.655 [0x80c862300] DEBUG - Auth: authenticated user 4877713 as User11111
Apr 26, 2019 05:17:24.656 [0x80cccb900] DEBUG - Request: [USERIPADDRESS:41737 (WAN)] POST /log (20 live) TLS GZIP Signed-in Token (User11111)
Apr 26, 2019 05:17:24.656 [0x80cccb900] WARN - [Chromecast] [Player] Buffering detected, last position change was 543ms ago
Apr 26, 2019 05:17:24.657 [0x80c862800] DEBUG - Completed: [USERIPADDRESS:41737] 200 POST /log (20 live) TLS GZIP 0ms 274 bytes (pipelined: 1)
Apr 26, 2019 05:17:24.672 [0x80daef500] DEBUG - Request: [USERIPADDRESS:41738 (WAN)] OPTIONS /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=1705&playQueueItemID=565889&state=buffering&hasMDE=1&time=67000&duration=5458000 (21 live) TLS GZIP Signed-in
Apr 26, 2019 05:17:24.672 [0x80c862800] DEBUG - Completed: [USERIPADDRESS:41738] 200 OPTIONS /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=1705&playQueueItemID=565889&state=buffering&hasMDE=1&time=67000&duration=5458000 (21 live) TLS GZIP 0ms 598 bytes (pipelined: 1)
Apr 26, 2019 05:17:24.913 [0x80cccb900] DEBUG - Request: [USERIPADDRESS:41730 (WAN)] OPTIONS /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=2337&playQueueItemID=565889&state=buffering&hasMDE=1&time=67000&duration=5458000 (21 live) TLS GZIP Signed-in
Apr 26, 2019 05:17:24.914 [0x80c862300] DEBUG - Completed: [USERIPADDRESS:41730] 200 OPTIONS /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=2337&playQueueItemID=565889&state=buffering&hasMDE=1&time=67000&duration=5458000 (21 live) TLS GZIP 0ms 598 bytes (pipelined: 8)
Apr 26, 2019 05:17:25.198 [0x80cccdc00] WARN - Held transaction for too long (../Statistics/StatisticsManager.cpp:249): 0.156250 seconds
Apr 26, 2019 05:17:25.448 [0x80c862800] DEBUG - Auth: authenticated user 4877713 as User11111
Apr 26, 2019 05:17:25.448 [0x80c862300] DEBUG - Auth: authenticated user 4877713 as User11111
Apr 26, 2019 05:17:25.449 [0x80daef500] DEBUG - Request: [USERIPADDRESS:41733 (WAN)] POST /log (20 live) TLS GZIP Signed-in Token (User11111)
Apr 26, 2019 05:17:25.449 [0x80daef500] WARN - [Chromecast] [Player] Buffering detected, last position change was 507ms ago
Apr 26, 2019 05:17:25.449 [0x80cccb900] DEBUG - Request: [USERIPADDRESS:41737 (WAN)] GET /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=1705&playQueueItemID=565889&state=buffering&hasMDE=1&time=67000&duration=5458000 (19 live) TLS GZIP Signed-in Token (User11111)
Apr 26, 2019 05:17:25.449 [0x80c862800] DEBUG - Completed: [USERIPADDRESS:41733] 200 POST /log (19 live) TLS GZIP 0ms 274 bytes (pipelined: 4)
Apr 26, 2019 05:17:25.450 [0x80cccb900] DEBUG - Client [j9ala9p21nsk7etqnmqodvhy] reporting timeline state buffering, progress of 67000/5458000ms for guid=, ratingKey=221583 url=, key=/library/metadata/221583, containerKey=, metadataId=221583, source=
Apr 26, 2019 05:17:25.455 [0x80c862300] DEBUG - Auth: authenticated user 4877713 as User11111
Apr 26, 2019 05:17:25.455 [0x80daef500] DEBUG - Request: [USERIPADDRESS:41739 (WAN)] GET /subtitles/:/transcode/universal/start?hasMDE=1&path=%2Flibrary%2Fmetadata%2F221583&mediaIndex=0&partIndex=0&protocol=http&fastSeek=1&directPlay=1&directStream=1&subtitleSize=100&audioBoost=100&location=wan&maxVideoBitrate=1500&directStreamAudio=1&mediaBufferSize=30720&session=tl3is0u9yss2hldpz4imc2n1&offset=68&subtitles=sidecar&copyts=1 (19 live) TLS GZIP Signed-in Token (User11111)
Apr 26, 2019 05:17:25.455 [0x80cccc800] DEBUG - Request: [USERIPADDRESS:41740 (WAN)] OPTIONS /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=2337&playQueueItemID=565889&state=playing&hasMDE=1&time=68000&duration=5458000 (19 live) TLS GZIP Signed-in
Apr 26, 2019 05:17:25.455 [0x80daef500] DEBUG - Found session GUID of tl3is0u9yss2hldpz4imc2n1 in session start.
Apr 26, 2019 05:17:25.456 [0x80c862800] DEBUG - Completed: [USERIPADDRESS:41740] 200 OPTIONS /:/timeline?ratingKey=221583&key=%2Flibrary%2Fmetadata%2F221583&playbackTime=2337&playQueueItemID=565889&state=playing&hasMDE=1&time=68000&duration=5458000 (19 live) TLS GZIP 0ms 598 bytes (pipelined: 1)
Apr 26, 2019 05:17:25.456 [0x80daef500] DEBUG - TranscodeUniversalRequest: using augmented profile Chromecast
Apr 26, 2019 05:17:25.456 [0x80daef500] DEBUG - Downloading document http://127.0.0.1:32400/library/metadata/221583?checkFiles=1&includeBandwidths=1&offset=68&X-Plex-Incomplete-Segments=1&X-Plex-Session-Identifier=j9ala9p21nsk7etqnmqodvhy
Apr 26, 2019 05:17:25.456 [0x80daef500] DEBUG - Auth: authenticated user 4877713 as User11111
Apr 26, 2019 05:17:25.462 [0x80daef500] DEBUG - We're going to try to auto-select an audio stream for account 4877713.
Apr 26, 2019 05:17:25.462 [0x80daef500] DEBUG - Selecting best audio stream for part ID 2266194 (autoselect: 1 language: en)
Apr 26, 2019 05:17:25.462 [0x80daef500] DEBUG - We're going to try to auto-select a subtitle.
Apr 26, 2019 05:17:25.462 [0x80daef500] DEBUG - Audio Stream: 4647349, Subtitle Stream: -1
Apr 26, 2019 05:17:25.462 [0x80daef500] DEBUG - Cleaning directory for session tl3is0u9yss2hldpz4imc2n1 ()
Apr 26, 2019 05:17:25.463 [0x80daef500] DEBUG - Starting a transcode session tl3is0u9yss2hldpz4imc2n1 at offset -1.0 (state=3)
2

Iā€™m on FreeNAS-11.1-U7 with Plex in an old style jail. I had to do some editing to get the server settings available again and that was pushing the limits of my freenas knowledge.

For at least the last couple of weeks and both before and after the editing (I think) I have been getting signal 10 messages in the email messages i get from freenas. I thought the editing might fix it but it didnā€™t.

the message I get each day is -

freenas.local kernel log messages:

pid 63535 (Plex Media Scanner), uid 972: exited on signal 10 pid 63556
(Plex Media Scanner), uid 972: exited on signal 10 pid 63610 (Plex
Media Scanner), uid 972: exited on signal 10 pid 63616 (Plex Media
Scanner), uid 972: exited on signal 10 pid 63617 (Plex Media Scanner),
uid 972: exited on signal 10

ā€“ End of security output ā€“

Everything seems to be working OK so Iā€™ve just been ignoring the messages assuming a future update might take care of it. Iā€™ve not looked at Plex logs.

3

That is essentially what I get as well in the console in freenas. However, when it exits it does not restart. I am currently looking at monit to fix this somehow, but I feel it shouldnt be exiting in any case. Its one thing if I am pushing my system at the time and resources arent there, but when no one is utilizing the system? Shouldnt be.

4

Well signal 10 is SIGBUS and related to memory access (indicates an access to an invalid address).

Can you post or dm full dmesg and pms Logs?

Also can yo replicate this as see how is the memory usage on the box when that playback (assuming transcode process is started) ?

5

That goes over my head mostly so I take it that request is for zachmal.

My freenas just has computer backups and media for Plex. Only one user for Plex and that use is mainly music and picture display. Maybe one or 2 videos played per week so essentially the system is idle a lot of the time when these messages are generated.

I was thinking the reference to media scanner was something to do with a refresh during idle time but that was just a guess.

If you want to explain in idiot terms how to get the info requested Iā€™m happy to try.

6

@Muddro replied to you DM not sure yet what it might be and might need more logs.

@Robert_MP dmesg is a shell command. If you donā€™t know how/where to run that youā€™ll probably find help in FreeNAS guides/faq (but it should be as easy as clicking the ā€œShellā€ icon on FreeNAS UI.

As for logs thereā€™s a easy way to get them via the PMS API, and we make that even easier via the Web App:

  • Go to Settings > Manage > Troubleshooting in Plex Web App
  • Click the Download Logs button

This should save a ZIP with all logs (pms, scanner etc).

You can find more help about that and getting the logs manually in our support articles: https://support.plex.tv/articles/200250417-plex-media-server-log-files/

Do note that this might show sensitive information that you might not want to share, you are free to send those over DM (and/or replace sensitive info like usernames/ips etc) so they are not publicly exposed in the forums.

7

Not sure there would be anything in my logs to worry about but have sent to you as a message.

Thanks for looking into this. I see today 1.15.4.993 is showing as an available update but Iā€™ll wait a day or 2 before trying it. I assume PMS_Updater.sh etc that I paste in to the shell window will still work ok now Iā€™ve updated rc.d as per another thread here?

As you can probably tell I just wanted a reliable nas that could run plex. I only understand as much as I need to about FreeNAS / BSD to set it up and keep it going.

8

Actually @Muddro DM his logs too and commented the update seems to have fixed things (at least so far)

I did noticed that what is crashing for you really only the Scanner, not PMS so at least we can be sure of that, I asked for another command output to help me matched the timestamps.

9

Actually it was good for a day or two and started occurign again. Mix between signal 10 and 11s

10

Have more relevant info. So, the Plex client gets an h3 (decode error) on an LG UH615V.

For certain videos it recreates the problem. Sending debug log through dm to you

11

Sorry I donā€™tā€™ see any reference to such error on the log you sentā€¦ is this shown in the clients?

12

Yes, they snapped a pic of it on their end.

IMG-20190503-WA0002
IMG-20190503-WA0002530Ɨ943 26.9 KB

1 Like
13

@Robert_MP youā€™re issue is different its the scanner thatā€™s exiting on sig 10 and seems to be restarting after.

I donā€™t see any errors in logs, but I do see its scanning quite a lot of content particularly photos, can you check the ram usage with top when this happens? Is it using a lot of RAM and eventually dies?

14

Hum this seems like a client issue and not related to the original post, to be clear PMS is not segfaulting when this happens right?

If so it might be best to post in the web/smarttv playerā€™s sectionā€¦

Actually seems like this is not new: Plex for LG - "Error code: h3 (decode)"

Might be a good idea to post here that youā€™re seeing the same issue

1 Like
15

The email messages are sent at 3am. If that is when the scanner fails Iā€™ll not be there to see it.
Will typing ā€˜topā€™ into the shell window tell you anything useful at other times or can I initiate a scan and then do it?
My freenas has all our old digital photos on it including lots of scans from negs and prints as well so yes there are a lot of photos but there has been no major change since long before the error messages started. There are home videos that never change and only a few movies / series so photos and mp3/flac music mainly

16

You could try to start a manual scan, but the ones that happen at night do deep analyses and this is more complex and costly.

One way to try and repo would be to create a new Library that points the the same media others do, since itā€™s first time scanning you might be able to trigger the crash. But this could be with any type of library so it might take you a bit to trigger it.

The output of top even outside of the crash might still be useful for comparison, feel free for dm that to me.

17

I did try your top command but didnā€™t see anything obvious as it was only repeating the error messages i get by email. maybe it would have told you more but anyway it may be too late now.
I ran the PMS_Updater.sh script today to update the server. It ran to a point then appeared to freeze so I left it a while then closed the shell window. The server was down. So i restarted the freenas box and tried the script again. It ran all the way through this timeā€¦ but PMS is still ā€˜not availableā€™.
Iā€™m not worried about watched states and metadata so the idea of a fresh install of Plex is ok. Iā€™m thinking I should update freenas to 11.2 and then install PMS using the new plugin.
Not being a freenas expert iā€™m looking for a walkthrough and so far not finding one that does all i want.
My media is on hard drives in freenas but my Plex data is on a 120G SSD and it is getting the new plex stored on the SSD that is still confusing me. Iā€™ll carry on reading for a day or 2 before i try any upgrades and replacement of Plex.

18

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.