Analyze not being run or failing when adding media

Plex Media Server
1

Server Version#: 1.30.1.6497 and earlier (since October 2022)

My media folder is on a NAS and PMS on Shield accesses the NAS.
When a new movie or TV show is added it can take 2-3 days before the analysis happens. This didn’t use to be the case. I can’t play the file until the analysis happens, because PMS doesn’t know what’s in the file. This applies equally to file that I add directly to the NAS and files added by PMS through DVR.

If I manually trigger analysis the analysis happens in a few seconds, so I know it isn’t a problem with it taking a long time. I don’t have thumbnails or other stuff that requires scanning the file.

I have another PMS instance running on my NAS, and I don’t experience this problem. The analysis happens right away. I compared setting between the two servers, but didn’t see anything of note.

I tried to look in the logs, but I’m not experienced enough to know what I’m looking for. I didn’t see anything in particular (such as errors).

I have PMS set to scan the library files once an hour. For the past few years when this happens any new media shows up and is playable when it shows up. Now it shows up, but without the analysis happening.

I also deleted the library from PMS on the shield and added it again, and that didn’t help either.

2

PMS does 2 analysis. 1 when a file is added and a deep analysis overnight during the scheduled task session. You should be able to play the file as soon as it’s added and scanned by PMS. If you have to wait something is wrong. There are other things that also happen during the schedules task session so if you don’t allow enough time for all of these to run, it may not get to all of them. Check how much time you are allowing and see if raising that helps.

3

The problem I’m seeing is with the first analysis. It has the appearance of not happening. What should I check for in the logs to see if it is or is not happening?

Is there an option that disables the first analysis? Perhaps it got set accidentally.

Also I thought I disabled all the extensive analysis options such as thumbnails (takes too much space on the shield’s limited disk space despite adding extra space none of the apps will use), but I’ll add more time. It’s already set for 3 hours.

4

Nope it’s automatically done when adding a file. What makes you think it’s not running? Do you see the codec info? If so, then it ran.

If the above is broken, can you reproduce with 1 file and provide me your server logs.

5

I believe the first phase of the analysis isn’t running since I don’t see any information about the codec or other relevant file information.

image
image941×791 43.1 KB

Here are the logs as of right now.

Last night two shows were recorded with two instances of PMS DVR.
PMS Shield: Law & Order (1990) - S22E11 - Second Chance.ts
PMS NAS: So Help Me Todd (2022) - S01E11 - Side Effects May Include Murder.ts

Late last night, both of these files failed to show any of their media information such as the codecs or video resolution on the Shield PMS.

Tonight the Law & Order episode is showing its information.

The episode of Law & Order was recorded using PMS on the Shield and the episode of So Help Me Todd was recorded using PMS on the NAS. While this might seem like a coincidence that the episode recorded on the Shield has its analysis information after a day, I’ve seen plenty of cases where this is not true.

Both PMS instances record to the NAS.

Plex Media Server Logs_2023-01-13_19-57-20.zip (7.0 MB)

6

@anon18523487 Were those logs sufficient to see any issues?

Did you need me to try something specific?

Thanks!

7

Strange. It looks like PMS successfully saved the recording of Law & Order. It sees the codec info.

Jan 12, 2023 20:03:29.670 [26255] DEBUG - [Grabber/01c711a0859808d1036901f5dfe8478612597cbc] [MI] * [mpegts mpeg2video/ac3] Duration: 3900835ms, 1920x1080 (1.777778) 29.970fps, bitrate=12396kbps, audio channels=6, optimizedForStreaming=0 (“/storage/LCMD-DATA/Media/TV Shows/.grab/01c711a0859808d1036901f5dfe8478612597cbc-9d5d4f4aa8f4bbcbb62b20b17603b461e64e15c3/Law && Order (1990) - S22E11 - Second Chance.ts”)

Someone tries to play the file later that night and PMS knows the info still.

Jan 13, 2023 00:13:08.113 [2823] DEBUG - [Req#165157/Transcode] MDE: E11 - Second Chance: no direct play video profile exists for http/mpegts/mpeg2video/ac3

It then does the deep analysis later that night during the scheduled task window.

Jan 13, 2023 02:04:38.387 [24572] DEBUG - Butler: Scheduling deep analysis for: Second Chance

This part fails.

Jan 13, 2023 02:04:42.092 [13033] DEBUG - Jobs: ‘/data/app/~~S-AsMrgCdex–Grb29lolg==/com.plexapp.mediaserver.smb-mKaN162UPI-xo0in657_mA==/lib/arm64/libPlexMediaScanner.so’ exit code for process 24584 is -9 (signal: Killed)

Although this fails, it should not have removed the information it had already analyzed. I’ll have to check if there is a problem here, but so far I don’t see why it wouldn’t show the codec info for this recording.

I can’t check So Help me Todd in your image above since that was on a different server. Next time something records, can you check it a few minutes after it’s done to see if the codec info is there. If not, get me the xml info for this new recording and a new PMS log.

8

@anon18523487 Thanks for the reply.

I set up a one-off recording of “The Beverly Hillbillies”. There was no codec information, so I opened up the XML info.

One thing of note is that when I try to retrieve the XML info for a recording with no codec, it takes 15-20 seconds to appear whereas those with codecs take only a few moments (< 1 sec).

<MediaContainer size="1" allowSync="1" identifier="com.plexapp.plugins.library" librarySectionID="2" librarySectionTitle="TV Shows" librarySectionUUID="ee77cfbe-7c4b-400b-8e3d-aa807a4d5c27" mediaTagPrefix="/system/bundle/media/flags/" mediaTagVersion="1673283781">
<Video ratingKey="16792" key="/library/metadata/16792" parentRatingKey="16791" grandparentRatingKey="16790" guid="plex://episode/5fc6b3815c7239002d39c44b" parentGuid="plex://season/5fc696eb139621002d3c97e9" grandparentGuid="plex://show/5fc696eb139621002d3c97e9" type="episode" title="Home for Christmas" grandparentKey="/library/metadata/16790" parentKey="/library/metadata/16791" librarySectionTitle="TV Shows" librarySectionID="2" librarySectionKey="/library/sections/2" grandparentTitle="The Beverly Hillbillies" parentTitle="Season 1" summary="When Granny, Uncle Jed, Elly May and Jethro decide to return to the country for the holidays, they discover airline travel." index="13" parentIndex="1" year="1962" thumb="/library/metadata/16792/thumb/1674617632" art="/library/metadata/16792/art/1674617632" grandparentThumb="/library/metadata/16790/thumb/1674617631" grandparentArt="/library/metadata/16790/art/1674617631" duration="1800000" originallyAvailableAt="1962-12-19" addedAt="1674617611" updatedAt="1674617632" oneShot="1">
<Media id="23400" beginOffset="395" channelIdentifier="5fc76e1c65aabb002d5ab42d-5fc705f6678e02002eccfec3" mediaGrabBeginsAt="1674615600" mediaGrabDevice="device://tv.plex.grabbers.hdhomerun/10548634" mediaGrabPartialRecording="1" mediaGrabPartialRecordingReason="The recording was cancelled" mediaGrabStatus="complete" origin="dvr">
<Part id="23575" key="/library/parts/23575/1674617580/file.ts" file="/storage/LCMD-DATA/Media/TV Shows/The Beverly Hillbillies (1962)/Season 01/The Beverly Hillbillies (1962) - S01E13 - Home for Christmas.ts" size="446831256"/>
</Media>
<Genre id="62866" filter="genre=62866" tag="Holiday"/>
<Genre id="62860" filter="genre=62860" tag="Sitcom"/>
<Genre id="26454" filter="genre=26454" tag="Entertainment"/>
<Channel id="62865" filter="channel=62865" tag="4.2 KTVXDT2 (MeTV)"/>
<Field locked="1" name="thumb"/>
<Field locked="1" name="art"/>
<Extras size="0"> </Extras>
<Related> </Related>
</Video>
</MediaContainer>

Here are the logs too.
Plex Media Server Logs_2023-01-24_20-41-05.zip (3.5 MB)

9

Interesting info in your XML.

mediaGrabPartialRecording=“1” mediaGrabPartialRecordingReason=“The recording was cancelled”

Could be related to what I see in your log.

Jan 24, 2023 20:33:00.982 [27154] ERROR - [Req#43a34b/Transcode/083d58c3-fc44-426f-ab98-c480829aa926/bad5ae4f-42d5-4e39-a822-802f8d39807f] Error closing file /storage/LCMD-DATA/Media/TV Shows/.grab/76ea34fd2eb6ff55b957694b9216c7aea46059c7-9d5d4f4aa8f4bbcbb62b20b17603b461e64e15c3/The Beverly Hillbillies (1962) - S01E13 - Home for Christmas.ts: Operation not permitted

Something is keeping the file from being properly closed. Since you are saving to the same location your Linux server also accesses, could it be something on that machine is keeping this file open? An anti-virus program or RSync if you use that for something? If you are willing to test this, turn off PMS on your Linux machine when the next thing is set to record from the Shield and see if the problem still exists.

10

@anon18523487,

I’ve done that experiment, and I’m not seeing any codec data in the XML info. I manually set it to record an episode that was already in the middle of broadcast, then let it record to the end. I didn’t stop it manually.

<MediaContainer size="1" allowSync="1" identifier="com.plexapp.plugins.library" librarySectionID="2" librarySectionTitle="TV Shows" librarySectionUUID="ee77cfbe-7c4b-400b-8e3d-aa807a4d5c27" mediaTagPrefix="/system/bundle/media/flags/" mediaTagVersion="1673283781">
<Video ratingKey="16799" key="/library/metadata/16799" parentRatingKey="16798" grandparentRatingKey="16797" guid="plex://episode/5fc6d512336b43002e0f984d" parentGuid="plex://season/5fc698483f000e002df38870" grandparentGuid="plex://show/5fc698483f000e002df38870" type="episode" title="Remembrance of Flings Past" grandparentKey="/library/metadata/16797" parentKey="/library/metadata/16798" librarySectionTitle="TV Shows" librarySectionID="2" librarySectionKey="/library/sections/2" grandparentTitle="Wings" parentTitle="Season 6" summary="While Joe awaits the results of a paternity test, Helen gets ready to celebrate a romantic Valentine's Day." index="17" parentIndex="6" year="1995" thumb="/library/metadata/16799/thumb/1674689651" art="/library/metadata/16799/art/1674689651" grandparentThumb="/library/metadata/16797/thumb/1674689651" grandparentArt="/library/metadata/16797/art/1674689651" duration="1800000" originallyAvailableAt="1995-02-14" addedAt="1674689612" updatedAt="1674689651" oneShot="1">
<Media id="23405" beginOffset="976" channelIdentifier="5fc76e1c65aabb002d5ab42d-5fc705f2c40548002d54577c" mediaGrabBeginsAt="1674687600" mediaGrabDevice="device://tv.plex.grabbers.hdhomerun/10548634" mediaGrabPartialRecording="1" mediaGrabPartialRecordingReason="The recording was cancelled" mediaGrabStatus="complete" origin="dvr">
<Part id="23580" key="/library/parts/23580/1674689581/file.ts" file="/storage/LCMD-DATA/Media/TV Shows/Wings (1990)/Season 06/Wings (1990) - S06E17 - Remembrance of Flings Past.ts" size="276816840"/>
</Media>
<Genre id="62866" filter="genre=62866" tag="Holiday"/>
<Genre id="62860" filter="genre=62860" tag="Sitcom"/>
<Genre id="26454" filter="genre=26454" tag="Entertainment"/>
<Channel id="62885" filter="channel=62885" tag="4.3 KTVXDT3 (REWIND TV)"/>
<Field locked="1" name="thumb"/>
<Field locked="1" name="art"/>
<Extras size="0"> </Extras>
<Related> </Related>
</Video>
</MediaContainer>

I made sure the other PMS wasn’t running. I’ve attached the logs.
Plex Media Server Logs_2023-01-25_16-37-39.zip (5.6 MB)

As another pointer of data, I’m seeing an issue with files that are recorded by the other PMS and “appear” to the Shield PMS. I’ve also seen this where I copy a file onto the NAS after ripping from my own collection.

This is the XML info from a file recorded by the other PMS:

<MediaContainer size="1" allowSync="1" identifier="com.plexapp.plugins.library" librarySectionID="2" librarySectionTitle="TV Shows" librarySectionUUID="ee77cfbe-7c4b-400b-8e3d-aa807a4d5c27" mediaTagPrefix="/system/bundle/media/flags/" mediaTagVersion="1673283781">
<Video ratingKey="16795" key="/library/metadata/16795" parentRatingKey="11976" grandparentRatingKey="10160" guid="plex://episode/63b4dcb12e5a63e0f2dad75b" parentGuid="plex://season/62b4eff4fb5a42db5cc6dea7" grandparentGuid="plex://show/605ccb39f898fb002d48cb44" type="episode" title="Someone She Knew" grandparentKey="/library/metadata/10160" parentKey="/library/metadata/11976" librarySectionTitle="TV Shows" librarySectionID="2" librarySectionKey="/library/sections/2" grandparentTitle="FBI: International" parentTitle="Season 2" contentRating="TV-14" summary="The team races to find a kidnapped American teen in Austria as the clock ticks on Forrester's reassignment." index="11" parentIndex="2" year="2021" thumb="/library/metadata/16795/thumb/1674622397" art="/library/metadata/10160/art/1674646239" grandparentThumb="/library/metadata/10160/thumb/1674646239" grandparentArt="/library/metadata/10160/art/1674646239" grandparentTheme="/library/metadata/10160/theme/1674646239" duration="3899993" originallyAvailableAt="2023-01-24" addedAt="1674622307" updatedAt="1674622397">
<Media id="23403" duration="3899993">
<Part id="23578" key="/library/parts/23578/1674619380/file.ts" duration="3899993" file="/storage/LCMD-DATA/Media/TV Shows/FBI International (2021)/Season 02/FBI International (2021) - S02E11 - Someone She Knew.ts" size="4454083404" deepAnalysisVersion="6" requiredBandwidths="11928,11546,10908,10908,10908,10908,10908,10908"/>
</Media>
<Guid id="tmdb://4159935"/>
<Guid id="tvdb://9538904"/>
<Extras size="0"> </Extras>
<Related> </Related>
</Video>
</MediaContainer>
11

I’m seeing the same access error with this file.

Jan 25, 2023 16:33:01.767 [13156] ERROR - [Req#4a167e/Transcode/3f7e0cf8-ef13-4b92-b430-1d4e8f8a00c0/79727da6-1b8d-43a2-ab75-006a81f10335] Error closing file /storage/LCMD-DATA/Media/TV Shows/.grab/a6c984006dce011a281e00e0eaaf903a957c7f22-9d5d4f4aa8f4bbcbb62b20b17603b461e64e15c3/Wings (1990) - S06E17 - Remembrance of Flings Past.ts: Operation not permitted

12

@anon18523487 ,

There must be something subtle going on, since a manual analysis yields results. It’s not like PMS can’t access the file since it wrote it in this case.

Note that the path being shown is the .grab location. Perhaps the DVR moved the file before the analysis realizes this and thus can’t deal with the moved file. I believe SMB doesn’t deal with moving files the same way a linux file system would.

I’m not sure how that hypothesis holds up to the issue that I see when I add files to the library by copying them onto the NAS directly instead of the DVR. That case is still broken.

I’m looking at the Plex Media Scanner Analysis.log family of logs and I see that the episode of Wings, “Remembrance of Flings Past” shows up in several iterations of the log.
Plex Media Scanner Analysis.log: Jan 25, 2023 16:36:04.655
Plex Media Scanner Analysis.1.log:Jan 25, 2023 16:35:05.383
Plex Media Scanner Analysis.2.log:Jan 25, 2023 16:33:33.640

The same with the F.B.I. episode, “Some She Knew” that was recorded by the other PMS (example of a media file showing up on disk).

I think the “Error closing file” is potentially a red herring, and the real issue is somewhere else.

13

Was discussing this with @anon18523487 -
There was a transcoder error closing the file in the .grab file at 16:33:01.767

Jan 25, 2023 16:33:01.767 [13156] ERROR - [Req#4a167e/Transcode/3f7e0cf8-ef13-4b92-b430-1d4e8f8a00c0/79727da6-1b8d-43a2-ab75-006a81f10335] Error closing file /storage/LCMD-DATA/Media/TV Shows/.grab/a6c984006dce011a281e00e0eaaf903a957c7f22-9d5d4f4aa8f4bbcbb62b20b17603b461e64e15c3/Wings (1990) - S06E17 - Remembrance of Flings Past.ts: Operation not permitted

The transcoder process exited at 16:33:01.817

Jan 25, 2023 16:33:01.817 [20728] DEBUG - Jobs: '/data/app/~~S-AsMrgCdex--Grb29lolg==/com.plexapp.mediaserver.smb-mKaN162UPI-xo0in657_mA==/lib/arm64/libPlexTranscoder.so' exit code for process 12951 is 0 (success)

At 16:33:01.825 the file in the .grab directory was opened by Plex Media Server process

Jan 25, 2023 16:33:01.826 [14405] DEBUG - [Grabber/a6c984006dce011a281e00e0eaaf903a957c7f22] [MI] Opening input file: "/storage/LCMD-DATA/Media/TV Shows/.grab/a6c984006dce011a281e00e0eaaf903a957c7f22-9d5d4f4aa8f4bbcbb62b20b17603b461e64e15c3/Wings (1990) - S06E17 - Remembrance of Flings Past.ts"

and

Jan 25, 2023 16:33:01.830 [14405] DEBUG - [Grabber/a6c984006dce011a281e00e0eaaf903a957c7f22] [FFMPEG] - Opening '/storage/LCMD-DATA/Media/TV Shows/.grab/a6c984006dce011a281e00e0eaaf903a957c7f22-9d5d4f4aa8f4bbcbb62b20b17603b461e64e15c3/Wings (1990) - S06E17 - Remembrance of Flings Past.ts' for reading

and did read from the file

Jan 25, 2023 16:33:01.892 [14405] DEBUG - [Grabber/a6c984006dce011a281e00e0eaaf903a957c7f22] [FFMPEG] - Before avformat_find_stream_info() pos: 0 bytes read:32768 seeks:0 nb_streams:2

and some info extracted and file closed

Jan 25, 2023 16:33:31.953 [14405] DEBUG - [Grabber/a6c984006dce011a281e00e0eaaf903a957c7f22] [MI]  *  [mpegts mpeg2video/ac3] Duration: 1121753ms, 704x480 (1.777778) 29.970fps, bitrate=1974kbps, audio channels=2, optimizedForStreaming=0 ("/storage/LCMD-DATA/Media/TV Shows/.grab/a6c984006dce011a281e00e0eaaf903a957c7f22-9d5d4f4aa8f4bbcbb62b20b17603b461e64e15c3/Wings (1990) - S06E17 - Remembrance of Flings Past.ts")

Jan 25, 2023 16:33:31.957 [14405] DEBUG - [Grabber/a6c984006dce011a281e00e0eaaf903a957c7f22] [MI] Chapters had generic titles, clearing.
Jan 25, 2023 16:33:31.957 [14405] DEBUG - [Grabber/a6c984006dce011a281e00e0eaaf903a957c7f22] [MI] Closing input file: "/storage/LCMD-DATA/Media/TV Shows/.grab/a6c984006dce011a281e00e0eaaf903a957c7f22-9d5d4f4aa8f4bbcbb62b20b17603b461e64e15c3/Wings (1990) - S06E17 - Remembrance of Flings Past.ts"

Then at 16:33:32.007 it got moved from the .grab directory

Jan 25, 2023 16:33:32.007 [14499] DEBUG - [Grabber/a6c984006dce011a281e00e0eaaf903a957c7f22] Assimilator: Moving "/storage/LCMD-DATA/Media/TV Shows/.grab/a6c984006dce011a281e00e0eaaf903a957c7f22-9d5d4f4aa8f4bbcbb62b20b17603b461e64e15c3/Wings (1990) - S06E17 - Remembrance of Flings Past.ts" to "/storage/LCMD-DATA/Media/TV Shows/Wings (1990)/Season 06/Wings (1990) - S06E17 - Remembrance of Flings Past.ts"

and analysis scanner job fired

Jan 25, 2023 16:33:32.563 [14916] DEBUG - [Grabber/a6c984006dce011a281e00e0eaaf903a957c7f22/JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/data/user/0/com.plexapp.mediaserver.smb/Plex\ Media\ Server/Codecs/583b3e4-4441-android-aarch64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx "/data/app/~~S-AsMrgCdex--Grb29lolg==/com.plexapp.mediaserver.smb-mKaN162UPI-xo0in657_mA==/lib/arm64/libPlexMediaScanner.so" --analyze --log-file-suffix " Analysis" --item 16799
Jan 25, 2023 16:33:32.568 [14916] DEBUG - [Grabber/a6c984006dce011a281e00e0eaaf903a957c7f22/JobRunner] Jobs: Starting child process with pid 14917

The Plex Media Scanner Analysis.2.log shows a 10 second delay in opening the file and also the log file

Jan 25, 2023 16:33:44.439 [14919] INFO - Plex Media Scanner v1.30.1.6497-5fc2e0894 - NVIDIA SHIELD Android TV darcy - build: android-aarch64 - GMT -07:00
Jan 25, 2023 16:33:44.439 [14919] INFO - Android version: 11, language: en-US
Jan 25, 2023 16:33:44.439 [14919] INFO - Processor: 4-core AArch64
Jan 25, 2023 16:33:44.439 [14919] INFO - /data/app/~~S-AsMrgCdex--Grb29lolg==/com.plexapp.mediaserver.smb-mKaN162UPI-xo0in657_mA==/lib/arm64/libPlexMediaScanner.so --analyze --log-file-suffix  Analysis --item 16799
Jan 25, 2023 16:33:33.402 [14917] DEBUG - Opening 20 database sessions to library (com.plexapp.plugins.library), SQLite 3.35.5, threadsafe=1
Jan 25, 2023 16:33:33.640 [14917] DEBUG - Analyzing media parts for item 16799 (Remembrance of Flings Past): 23405

Jan 25, 2023 16:33:33.648 [14917] DEBUG - [ID 23580] Media part analysis: /storage/LCMD-DATA/Media/TV Shows/Wings (1990)/Season 06/Wings (1990) - S06E17 - Remembrance of Flings Past.ts

Jan 25, 2023 16:33:44.223 [14917] DEBUG - [MI] Opening input file: "/storage/LCMD-DATA/Media/TV Shows/Wings (1990)/Season 06/Wings (1990) - S06E17 - Remembrance of Flings Past.ts"

Jan 25, 2023 16:33:44.223 [14917] DEBUG - [FFMPEG] - Opening '/storage/LCMD-DATA/Media/TV Shows/Wings (1990)/Season 06/Wings (1990) - S06E17 - Remembrance of Flings Past.ts' for reading

And the analysis job was force terminated 20 seconds after the job was started

Will need to discuss this with the development team

Update: We had seen NVIDIA SHIELD smb timing issues before and delays in opening files. This may be similar problem

14

It’s interesting you mentioned the 20 seconds delay. That’s roughly the time it takes to open the XML info document for an “unscanned” file. Once it’s been scanned it opens right away.

15

We have not been able to reproduce the issue. I would like to see new logs from the latest version of Plex Media Server - the current beta available for the NVIDIA SHIELD is 1.31.1.6716

The logs I looked at from your server were for version 1.30.1.6497

Could you try out on a new recording using the latest Plex Media Server beta

Please ensure you continue to have debug logging enabled for Plex Media Server.
Please wait 10 minutes after completion of a recording and then capture the server logs zip and also the media info xml for the recording

And if the problem is still happening - do a manual analyze and then at the end - capture the logs zip again and media info xml

It is possible that this was the issue resolved in Plex Media Server 1.30.2.6563

  • (DVR) Preview thumbs not being created for DVR recordings (#13943)
16

So all my PMS instances need to be on the latest beta version?

Are you testing with more than one PMS instance accessing the NAS?

I have three PMS instances.

I’ll get this data soon.

Thanks for looking into the issue.

17

No I am not - The temporary directories for the recordings within the .grab directory do have the server identifier in the directory names so multiple servers accessing the path should be ok - each server will have a different identifier in the recording media file path

The one that matters is the Shield that is failing to analyze the media at end of recordings - and there was a recent fix for an issue like this where post processing was not being run after recordings

So ensure the server that is doing the recordings is on the current beta which is 1.31.1.6716

I see you have 6 active servers - with one shield on 1.30.1.6497 and another on 1.27.2.5929

(Also notice you have a FreeBSD server on a very old version of PMS - 1.21.1.3830)

18

Plex Media Server Logs_2023-02-18_14-14-10-before-manual-analysis.zip (5.3 MB)
Plex Media Server Logs_2023-02-18_14-16-52-after-mystery-analysis.zip (5.3 MB)
Plex Media Server Logs_2023-02-18_14-19-21-after-manual-analysis.zip (5.2 MB)
xml-info.zip (5.8 KB)

OK, I made a short recording.
/storage/LCMD-DATA/Media/TV Shows/Lidia’s Kitchen (2013)/Season 10/Lidia’s Kitchen (2013) - S10E17 - Never Enough Pasta.ts

I captured the logs 10 minutes after the recording finished. I grabbed the logs. I took a look at the file info. There was no codec information, so I grabbed the XML info (before-manual-analysis.xml).

I went to go a do a manual analysis, but I noticed the codec information was now present. I captured another set of logs and XML info (after-mystery-analysis.xml).

I forced a manual analysis and captures logs and XML info again (after-manual-analysis.xml). I also compared the XML info from this and the after-mystery-analysis.xml and found no differences.

I recorded another show (no logs captured from this). It also exhibited the same behavior. No codec information, but viewing the XML info triggered something that caused the codec information to appear soon afterwards. I recorded a third show, and attempting to play the file (without viewing the XML info) doesn’t work (no video is played).

19

Thanks - I will have to see if we can reproduce it somehow. What I would need, is to capture a logcat using ADB when this happens - to look at with the server logs

The is evidence of a hung Plex Media Scanner Analysis job until it was killed

These two analysis processes hung
Started at

Feb 18, 2023 14:03:31.204 [14584] DEBUG - [Grabber/de0cce1a44ce4c5f2464116c156de5ad2a4b2175/JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/data/user/0/com.plexapp.mediaserver.smb/Plex\ Media\ Server/Codecs/7e8dc7a-4467-android-aarch64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx "/data/app/~~f4vOcpun_sXuzzjhPswqvQ==/com.plexapp.mediaserver.smb-8GpNKbQSpZoFkbX8-e5GiQ==/lib/arm64/libPlexMediaScanner.so" --analyze --log-file-suffix " Analysis" --item 16862
Feb 18, 2023 14:03:31.207 [14584] DEBUG - [Grabber/de0cce1a44ce4c5f2464116c156de5ad2a4b2175/JobRunner] Jobs: Starting child process with pid 14585

Hung at this point

Feb 18, 2023 14:03:31.458 [14586] INFO - Plex Media Scanner v1.31.1.6716-ca0c45ff8 - NVIDIA SHIELD Android TV darcy - build: android-aarch64 - GMT -07:00
. . . 
Feb 18, 2023 14:03:31.701 [14585] DEBUG - [MI] Opening input file: "/storage/LCMD-DATA/Media/TV Shows/Lidia's Kitchen (2013)/Season 10/Lidia's Kitchen (2013) - S10E17 - Never Enough Pasta.ts"

Feb 18, 2023 14:03:31.701 [14585] DEBUG - [FFMPEG] - Opening '/storage/LCMD-DATA/Media/TV Shows/Lidia's Kitchen (2013)/Season 10/Lidia's Kitchen (2013) - S10E17 - Never Enough Pasta.ts' for reading
. . .
Feb 18, 2023 14:03:31.713 [14585] DEBUG - [FFMPEG] - After avformat_find_stream_info() pos: 0 bytes read:1331344 seeks:2 frames:110

hung at 14:03:31.713 - was killed by Plex Media Server process at 14:03:51

Feb 18, 2023 14:03:51.207 [14584] DEBUG - [Grabber/de0cce1a44ce4c5f2464116c156de5ad2a4b2175] Signalling job ID 14585 with 9

and exited at 14:04:01

Feb 18, 2023 14:04:01.763 [12326] DEBUG - Jobs: '/data/app/~~f4vOcpun_sXuzzjhPswqvQ==/com.plexapp.mediaserver.smb-8GpNKbQSpZoFkbX8-e5GiQ==/lib/arm64/libPlexMediaScanner.so' exit code for process 14585 is -9 (signal: Killed)

Similarly the following job hung at 14:13:32
Started at this time

Feb 18, 2023 14:13:31.985 [15336] DEBUG - [Req#4115/JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/data/user/0/com.plexapp.mediaserver.smb/Plex\ Media\ Server/Codecs/7e8dc7a-4467-android-aarch64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx "/data/app/~~f4vOcpun_sXuzzjhPswqvQ==/com.plexapp.mediaserver.smb-8GpNKbQSpZoFkbX8-e5GiQ==/lib/arm64/libPlexMediaScanner.so" --analyze --log-file-suffix " Analysis" --item 16862
Feb 18, 2023 14:13:31.986 [15336] DEBUG - [Req#4115/JobRunner] Jobs: Starting child process with pid 15337

and got to the same position

Feb 18, 2023 14:13:32.118 [15338] INFO - Plex Media Scanner v1.31.1.6716-ca0c45ff8 - NVIDIA SHIELD Android TV darcy - build: android-aarch64 - GMT -07:00
Feb 18, 2023 14:13:32.118 [15338] INFO - Android version: 11, language: en-US
. . .
Feb 18, 2023 14:13:32.329 [15337] DEBUG - [MI] Opening input file: "/storage/LCMD-DATA/Media/TV Shows/Lidia's Kitchen (2013)/Season 10/Lidia's Kitchen (2013) - S10E17 - Never Enough Pasta.ts"
Feb 18, 2023 14:13:32.329 [15337] DEBUG - [FFMPEG] - Opening '/storage/LCMD-DATA/Media/TV Shows/Lidia's Kitchen (2013)/Season 10/Lidia's Kitchen (2013) - S10E17 - Never Enough Pasta.ts' for reading
. . .
Feb 18, 2023 14:13:32.370 [15337] DEBUG - [FFMPEG] - After avformat_find_stream_info() pos: 0 bytes read:1331344 seeks:2 frames:110

hung at 14:13:32.370
Killed by Plex Media Server at 14:14:01

Feb 18, 2023 14:14:01.986 [15336] DEBUG - [Req#4115] Signalling job ID 15337 with 9

and exited at 14:14:02

Feb 18, 2023 14:14:02.394 [12326] DEBUG - Jobs: '/data/app/~~f4vOcpun_sXuzzjhPswqvQ==/com.plexapp.mediaserver.smb-8GpNKbQSpZoFkbX8-e5GiQ==/lib/arm64/libPlexMediaScanner.so' exit code for process 15337 is -9 (signal: Killed)

But the next attempt did not hang

Feb 18, 2023 14:14:01.999 [15336] DEBUG - [Req#4115/JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/data/user/0/com.plexapp.mediaserver.smb/Plex\ Media\ Server/Codecs/7e8dc7a-4467-android-aarch64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx "/data/app/~~f4vOcpun_sXuzzjhPswqvQ==/com.plexapp.mediaserver.smb-8GpNKbQSpZoFkbX8-e5GiQ==/lib/arm64/libPlexMediaScanner.so" --analyze --log-file-suffix " Analysis" --item 16862
Feb 18, 2023 14:14:02.000 [15336] DEBUG - [Req#4115/JobRunner] Jobs: Starting child process with pid 15380

This got beyond the earlier jobs

Feb 18, 2023 14:14:02.398 [15380] DEBUG - [FFMPEG] - After avformat_find_stream_info() pos: 0 bytes read:1331344 seeks:2 frames:110

Feb 18, 2023 14:14:02.410 [15380] DEBUG - [MI]  * 3b85fced20bc58889d2ed0fdba8633c66f5826a5 [mpegts mpeg2video/ac3] Duration: 371010ms, 1920x1080 (1.777778) 29.970fps, bitrate=7813kbps, audio channels=6, optimizedForStreaming=0 ("/storage/LCMD-DATA/Media/TV Shows/Lidia's Kitchen (2013)/Season 10/Lidia's Kitchen (2013) - S10E17 - Never Enough Pasta.ts")
. . .
20

I’m going to try reproducing the behavior after disabling the other two instances of PMS that are accessing the NAS. I don’t have high hopes that it will affect anything, but I want to rule that out.