Problems after upgraded to 1.40.3

Plex Media Server NAS & Devices
1

Server Version#: 1.40.3
Player Version#: web

Hi, I have problems with my server since I have upgraded today. First, the server wasn’t responding but when i accessed it from web, it said there was a database upgrade in progress. After a while the database appeared completed.

Later tonight, i was watching an episode from my show on my PMS and suddenly i’ve lost connection. Could not find what was going on so I rebooted my SAN remotely but it didn’t solve the problem. I opened Plex from web and to my surprise, i got again the database upgrade message for a second time. I waited until it completed but i hear (the disks spinning) something else is going on.

My log file keep growing and growing. I have tons of log entries like the following related to transcoding whereas nothing actually plays:

un 16, 2024 21:15:56.917 [139911161236280] DEBUG - [Req#647e/Transcode] TranscodeUniversalRequest: using augmented profile Generic
Jun 16, 2024 21:15:56.917 [139911161236280] DEBUG - [Req#647e/Transcode] Downloading document http://127.0.0.1:32400/library/metadata/781891?checkFiles=1&includeBandwidths=1&offset=337&X-Plex-Incomplete-Segments=1&X-Plex-Session-Identifier=br6ni4jahhnqbr7y26576vad
Jun 16, 2024 21:15:56.917 [139911161236280] DEBUG - [Req#647e/Transcode/Req#647f] Auth: authenticated user 14725044 as Jonathan
Jun 16, 2024 21:15:56.933 [139911161236280] DEBUG - [Req#647e/Transcode] We’re going to try to auto-select an audio stream for account 14725044.
Jun 16, 2024 21:15:56.933 [139911161236280] DEBUG - [Req#647e/Transcode] Selecting best audio stream for part ID 1102624 (language: en)
Jun 16, 2024 21:15:56.933 [139911161236280] DEBUG - [Req#647e/Transcode] Audio Stream: 954522, Subtitle Stream: 954523
Jun 16, 2024 21:15:56.949 [139911161236280] DEBUG - [Req#647e/Transcode] Streaming Resource: Terminating session 0x7f3f9e7e6318:br6ni4jahhnqbr7y26576vad which is using 2kbps of WAN bandwidth. Used is now 0kbps
Jun 16, 2024 21:15:56.949 [139911161236280] DEBUG - [Req#647e/Transcode] Streaming Resource: Terminated session 0x7f3f9e7e6318:br6ni4jahhnqbr7y26576vad with reason Client stopped playback.
Jun 16, 2024 21:15:56.949 [139911161236280] DEBUG - [Req#647e/Transcode] Streaming Resource: Removing session 0x7f3f9e7e6318:br6ni4jahhnqbr7y26576vad
Jun 16, 2024 21:15:56.950 [139911161236280] DEBUG - [Req#647e/Transcode] Streaming Resource: Attempting to create AdHoc transcode session br6ni4jahhnqbr7y26576vad
Jun 16, 2024 21:15:56.950 [139911161236280] DEBUG - [Req#647e/Transcode] MDE: received PLEX_PROTOCOL_ANY from client, but could not determine best protocol. Defaulting to HTTP
Jun 16, 2024 21:15:56.950 [139911161236280] DEBUG - [Req#647e/Transcode] MDE: analyzing media item 1101949
Jun 16, 2024 21:15:56.950 [139911161236280] DEBUG - [Req#647e/Transcode] MDE: E3 - The Box: Direct Play is disabled
Jun 16, 2024 21:15:56.950 [139911161236280] DEBUG - [Req#647e/Transcode] MDE: E3 - The Box: no direct play video profile exists for http/mkv/hevc
Jun 16, 2024 21:15:56.950 [139911161236280] DEBUG - [Req#647e/Transcode] MDE: E3 - The Box: no direct play video profile exists for http/mkv/hevc/eac3
Jun 16, 2024 21:15:56.950 [139911161236280] DEBUG - [Req#647e/Transcode] MDE: E3 - The Box: transcoding selected subtitle stream
Jun 16, 2024 21:15:56.950 [139911161236280] DEBUG - [Req#647e/Transcode] MDE: Dark Matter (2024) - S1 E3 - The Box: selected media 0 / 1101949
Jun 16, 2024 21:15:56.950 [139911161236280] DEBUG - [Req#647e/Transcode] Streaming Resource: Adding session 0x7f3f9bc214b8:br6ni4jahhnqbr7y26576vad which is using 2kbps of WAN bandwidth. Used is now 2kbps
Jun 16, 2024 21:15:56.950 [139911161236280] DEBUG - [Req#647e/Transcode] Streaming Resource: Added session 0x7f3f9bc214b8:br6ni4jahhnqbr7y26576vad
Jun 16, 2024 21:15:56.951 [139911161236280] DEBUG - [Req#647e/Transcode] Streaming Resource: Reached Decision id=781891 codes=(General=1001,Direct play not available; Conversion OK. Direct Play=3000,App cannot direct play this item. Direct play is disabled. Transcode=1001,Direct play not available; Conversion OK.)

Also I see recurrent errors like this one:
Jun 16, 2024 21:26:22.868 [139911119350584] ERROR - [Req#6751] Failed to begin transaction (/home/runner/actions-runner/_work/plex-media-server/plex-media-server/Playlists/PlayQueueRequestHandler.cpp:257) (tries=1): Cannot begin transaction. database is locked

thank you if you can help.

2

stop server delete the folders cache codecs diagnostics scanners and try starting it again, wait a bit, stop, start again, see if that does it.

3

could you point me out on which folders exactly?

Btw, i see TONS of log entries like the following too. I feel there are gremlins in my PMS…

Any idea what’s going on, is this normal? Why does anything goes every single file of my server for doing this and other things?

Jun 18, 2024 06:38:52.121 [139756276140856] DEBUG - [MI] Chapters had generic titles, clearing.
Jun 18, 2024 06:38:52.122 [139756276140856] DEBUG - [MI] Closing input file: “/volume1/Pictures/#snapshot/GMT-04-2024.06.17-22.00.03/Onedrive copy (not online)/2019/12/20191225_023450000_iOS.MOV”
Jun 18, 2024 06:38:52.123 [139756276140856] DEBUG - Updating media item 1128010, size=71076361, metadata_item_id=808107
Jun 18, 2024 06:38:52.123 [139756276140856] DEBUG - Updating part with ID=1128685 [/volume1/Pictures/#snapshot/GMT-04-2024.06.17-22.00.03/Onedrive copy (not online)/2019/12/20191225_023450000_iOS.MOV]
Jun 18, 2024 06:38:52.154 [139756276140856] DEBUG - Updating metadata item (save) (20191225_023450000_iOS) with ID 808107
Jun 18, 2024 06:38:52.237 [139756276140856] DEBUG - Analyzing media parts for item 807370 (20191225_023707000_iOS): 1127278
Jun 18, 2024 06:38:52.302 [139756276140856] DEBUG - [ID 1127953] Media part analysis: /volume1/Pictures/#snapshot/GMT-04-2024.06.17-22.00.03/Onedrive copy (not online)/20191225_023707000_iOS.MOV
Jun 18, 2024 06:38:52.344 [139756276140856] DEBUG - [MI] Opening input file: “/volume1/Pictures/#snapshot/GMT-04-2024.06.17-22.00.03/Onedrive copy (not online)/20191225_023707000_iOS.MOV”
Jun 18, 2024 06:38:52.344 [139756276140856] DEBUG - [FFMPEG] - Opening ‘/volume1/Pictures/#snapshot/GMT-04-2024.06.17-22.00.03/Onedrive copy (not online)/20191225_023707000_iOS.MOV’ for reading
Jun 18, 2024 06:38:52.344 [139756276140856] DEBUG - [FFMPEG] - Setting default whitelist ‘file,crypto,data’
Jun 18, 2024 06:38:52.345 [139756276140856] DEBUG - [FFMPEG] - Format mov,mp4,m4a,3gp,3g2,mj2 probed with size=2048 and score=100
Jun 18, 2024 06:38:52.345 [139756276140856] DEBUG - [FFMPEG] - ISO: File Type Major Brand: qt
Jun 18, 2024 06:38:52.368 [139756276140856] DEBUG - [FFMPEG] - Unknown dref type 0x73696c61 size 12
Jun 18, 2024 06:38:52.369 [139756276140856] DEBUG - [FFMPEG] - Shifting DTS by 40 because of negative CTTS.
Jun 18, 2024 06:38:52.369 [139756276140856] DEBUG - [FFMPEG] - Processing st: 0, edit list 0 - media time: 0, duration: 68026
Jun 18, 2024 06:38:52.370 [139756276140856] DEBUG - [FFMPEG] - Unknown dref type 0x73696c61 size 12
Jun 18, 2024 06:38:52.370 [139756276140856] DEBUG - [FFMPEG] - Processing st: 1, edit list 0 - media time: 0, duration: 4999838
Jun 18, 2024 06:38:52.371 [139756276140856] DEBUG - [FFMPEG] - Unknown dref type 0x73696c61 size 12
Jun 18, 2024 06:38:52.371 [139756276140856] DEBUG - [FFMPEG] - Processing st: 2, edit list 0 - media time: 0, duration: 68026
Jun 18, 2024 06:38:52.371 [139756276140856] DEBUG - [FFMPEG] - Unknown dref type 0x73696c61 size 12
Jun 18, 2024 06:38:52.371 [139756276140856] DEBUG - [FFMPEG] - Processing st: 3, edit list 0 - media time: 0, duration: 68026
Jun 18, 2024 06:38:52.372 [139756276140856] DEBUG - [FFMPEG] - Before avformat_find_stream_info() pos: 113050780 bytes read:121159 seeks:1 nb_streams:4
Jun 18, 2024 06:38:52.372 [139756276140856] DEBUG - [FFMPEG] - nal_unit_type: 32(VPS), nuh_layer_id: 0, temporal_id: 0
Jun 18, 2024 06:38:52.372 [139756276140856] DEBUG - [FFMPEG] - Decoding VPS
Jun 18, 2024 06:38:52.372 [139756276140856] DEBUG - [FFMPEG] - Main profile bitstream
Jun 18, 2024 06:38:52.372 [139756276140856] DEBUG - [FFMPEG] - nal_unit_type: 33(SPS), nuh_layer_id: 0, temporal_id: 0
Jun 18, 2024 06:38:52.372 [139756276140856] DEBUG - [FFMPEG] - Decoding SPS
Jun 18, 2024 06:38:52.372 [139756276140856] DEBUG - [FFMPEG] - Main profile bitstream
Jun 18, 2024 06:38:52.372 [139756276140856] DEBUG - [FFMPEG] - Decoding VUI
Jun 18, 2024 06:38:52.373 [139756276140856] DEBUG - [FFMPEG] - nal_unit_type: 34(PPS), nuh_layer_id: 0, temporal_id: 0
Jun 18, 2024 06:38:52.373 [139756276140856] DEBUG - [FFMPEG] - Decoding PPS
Jun 18, 2024 06:38:52.373 [139756276140856] DEBUG - [FFMPEG] - nal_unit_type: 34(PPS), nuh_layer_id: 0, temporal_id: 0
Jun 18, 2024 06:38:52.373 [139756276140856] DEBUG - [FFMPEG] - Decoding PPS
Jun 18, 2024 06:38:52.375 [139756276140856] DEBUG - [FFMPEG] - All info found
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - [FFMPEG] - After avformat_find_stream_info() pos: 169961 bytes read:291084 seeks:2 frames:42
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - [MI] Opening “/volume1/Pictures/#snapshot/GMT-04-2024.06.17-22.00.03/Onedrive copy (not online)/20191225_023707000_iOS.MOV” for MP4 atom parsing
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Skipping ftyp atom of size 20 at offset 0
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Skipping wide atom of size 8 at offset 20
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Skipping mdat atom of size 112962361 at offset 28
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found moov atom of size 88391 at offset 112962389
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found trak atom of size 48894 at offset 112962505
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found trak atom of size 23560 at offset 113011399
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found trak atom of size 14754 at offset 113034959
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found trak atom of size 629 at offset 113049713
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found mdia atom of size 48690 at offset 112962709
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found minf atom of size 48601 at offset 112962798
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found stbl atom of size 48481 at offset 112962918
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found mdia atom of size 23424 at offset 113011535
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found minf atom of size 23335 at offset 113011624
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found stbl atom of size 23219 at offset 113011740
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found mdia atom of size 14586 at offset 113035127
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found minf atom of size 14494 at offset 113035219
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found stbl atom of size 14362 at offset 113035351
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found tref atom of size 32 at offset 113035095
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found mdia atom of size 461 at offset 113049881
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found minf atom of size 369 at offset 113049973
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found stbl atom of size 237 at offset 113050105
Jun 18, 2024 06:38:52.376 [139756276140856] DEBUG - Mp4AtomParser: Found tref atom of size 32 at offset 113049849

Also, i have TONS of log entries like “now watching”:
Jun 18, 2024 20:08:10.385 [139756180671288] DEBUG - [Req#8c17] [Notify] Now watching “/volume1/Pictures/#snapshot/GMT-04-2024.06.14-22.00.01/iPod Photo Cache/F00”
Jun 18, 2024 20:08:10.385 [139756180671288] DEBUG - [Req#8c17] [Notify] Now watching “/volume1/Pictures/#snapshot/GMT-04-2024.06.14-22.00.01/iPod Photo Cache/F01”
Jun 18, 2024 20:08:10.385 [139756180671288] DEBUG - [Req#8c17] [Notify] Now watching “/volume1/Pictures/#snapshot/GMT-04-2024.06.14-22.00.01/iPod Photo Cache/F02”
Jun 18, 2024 20:08:10.385 [139756180671288] DEBUG - [Req#8c17] [Notify] Now watching “/volume1/Pictures/#snapshot/GMT-04-2024.06.14-22.00.01/iPod Photo Cache/F03”
Jun 18, 2024 20:08:10.385 [139756180671288] DEBUG - [Req#8c17] [Notify] Now watching “/volume1/Pictures/#snapshot/GMT-04-2024.06.14-22.00.01/iPod Photo Cache/F04”
Jun 18, 2024 20:08:10.386 [139756180671288] DEBUG - [Req#8c17] [Notify] Now watching “/volume1/Pictures/#snapshot/GMT-04-2024.06.14-22.00.01/iPod Photo Cache/F05”
Jun 18, 2024 20:08:10.386 [139756180671288] DEBUG - [Req#8c17] [Notify] Now watching “/volume1/Pictures/#snapshot/GMT-04-2024.06.14-22.00.01/iPod Photo Cache/F06”
Jun 18, 2024 20:08:10.386 [139756180671288] DEBUG - [Req#8c17] [Notify] Now watching “/volume1/Pictures/#snapshot/GMT-04-2024.06.14-22.00.01/iPod Photo Cache/F07”
Jun 18, 2024 20:08:10.386 [139756180671288] DEBUG - [Req#8c17] [Notify] Now watching “/volume1/Pictures/#snapshot/GMT-04-2024.06.14-22.00.01/iPod Photo Cache/F08”
Jun 18, 2024 20:08:10.386 [139756180671288] DEBUG - [Req#8c17] [Notify] Now watching “/volume1/Pictures/#snapshot/GMT-04-2024.06.14-22.00.01/iPod Photo Cache/F09”
Jun 18, 2024 20:08:10.386 [139756180671288] DEBUG - [Req#8c17] [Notify] Now watching “/volume1/Pictures/#snapshot/GMT-04-2024.06.14-22.00.01/iPod Photo Cache/F10”
Jun 18, 2024 20:08:10.386 [139756180671288] DEBUG - [Req#8c17] [Notify] Now watching “/volume1/Pictures/#snapshot/GMT-04-2024.06.14-22.00.01/iPod Photo Cache/F11”
Jun 18, 2024 20:08:10.386 [139756180671288] DEBUG - [Req#8c17] [Notify] Now watching “/volume1/Pictures/#snapshot/GMT-04-2024.06.14-22.00.01/iPod Photo Cache/F12”

For testing, I have deleted a library and now it kicked on a database optimization and it has been running for over 15 min and still running.

Thank for any help.

6

Part of the problem is Plex is scanning the #snapshot folders. This will be fixed in an upcoming release (date tbd).

In the meantime, make the #snapshot folder invisible to Plex.

See: Scan results in hundreds of duplicate items in Music Library - #18 by Kubjo

Once that is done:

  1. Re-scan all libraries
  2. Empty Trash
  3. Clean Bundles
    dance

After the scan/empty trash/clean bundles is complete:

  1. Stop Plex Media Server and wait one minute.
  2. Start Plex Media Server and wait three minutes for Plex to log the startup sequence.
  3. Pull the server log files (Settings → Troubleshooting).
  4. Upload the entire zip file to the thread (drag it into the message window, it will insert at the cursor location).

We can then see if anything else needs addressing.

7

Just made the snapshots invisible while the server was stopped. When i restarted it, i got this message: Plex Media Server is currently running database migrations. It ran for ~2 minutes…

Now doing the next steps and will get back.

8

Plex Media Server Log.zip (217.8 KB)
here it is. I let the server running for a bit longer after i did what you instructed.

thank you for insights!

9

It looks like Plex is skipping the snapshot directories.

The problem is fixed in the current beta release: Plex Media Server - #629 by chris_decker08

10

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