Cleaning Bundles to infinity and beyond!

Plex Media Server Metadata & Adding Files
,
1

Server Version#: 1.28.1.6104 on a Raspberry Pi 3 running Raspian.
Player Version#: 4.90.1

The PMS has been stuck cleaning bundles around 75% for over a year now. I’ve reset the server, tried repairing the database, and updated the server & OS several times (I’ll be doing another update today). But it always ends up back in this perpetual cleaning bundles state.

Plex Bundles stuck

If anyone can tell me how to work around this, or if there are files I can manually delete to help the server avoid this sticky issue (without losing all user-viewing history) - I’m all ears.
This issue seems to clog up the server preventing it from updating other basic Metadata.

There are no errors in the console logs being thrown other than this unrelated annoying one every 40 seconds:
“SSDP: Error parsing device schema…”

2

At least it didn’t hang at 16383 :slight_smile:

And for over a year too! Geez.
The only thought I have would be to find what files are causing it to hang.
Is it also stuck on updating the metadata for those three items?

3

I force-stopped the PMS and have successfully updated it to the latest build: 1.28.2.6151.
When it gets stuck like that most metadata updates are blocked. I add new content and that new content will appear in the library, but most extra features are never loaded into that new asset’s bundle.

I just checked the integrity of the database and discovered several “row ### missing from index index_1items_on2”, where 1 = taggings, media_items, tags, & metadata_items - and 2 = tag_id, ends_at, media_analysis_version, deleted_at, media_item_id, key, hash, guide, & index.
The “row #s” showed only 1 with multiple entries (1 row missing a few things).

I also noticed that the database backups have stopped, likely when this metadata hang started (a couple of weeks ago) - prior to that, matching my server setting, the *.db was backed up every 3 days.

I seem to have managed to “recover” the DB through the operations listed in these support articles: repair-a-corrupted-database AND repair-an-old-db

I will wait and see how long this lasts, but I do wish PMS wouldn’t fail so silently. And now that I have this in writing I’ll be able to reference and compare when (not if) this occurs again.

Thanks for your time.

1 Like
4

Thanks for trying repair again. I read how you did that in the OP, too.
Also appreciate the repair an old db article that I never spotted.
It’s great how they include the SQLITE program now.

I’ve been using a Pi3 for PlexAmp, but I guess it’s fast enough to run a Plex Server with a heat sink maybe?

5

I have confirmed that the server is operational and no longer stuck cleaning bundles (for now). I am able to update metadata and see the full features expected from my media library.

No to derail the primary topic, but to answer your follow-up: I do not have a heat sink, and it has been working relatively well for a few years with this rather basic/bar-boned setup.
I have a few remote users on it who occasionally complain about lag due to transcoding… even locally I can encounter transcoding lag on higher quality video files. So I’d only truly recommend the Pi3 if it’s intended as a local Plex fix. For serving remotely I would invest in a more powerful solution.

6

Well, it seems that I spoke too soon.

image
It’s been less than 24 hours and the infinitely spinning bundles cleaning has returned.

I just did an integrity check on the database and it returned “okay” - so, this may not be a corrupted database issue.

Any ideas on how to figure out what file(s) are causing it to hang? Is there a verbose cleaning bundles log file I can hunt down? I glanced through the logs that I downloaded through Plex Web App > Settings > Manage > Troubleshooting, but there was very little useful info. Finding these logs is described in this support document.

7

Probably need to see your server logs to figure out what is going on.

8

I have disabled “Remove old bundles every week” (Settings > Scheduled Tasks) and rebooted the server to successfully break the current infinite bundle cleaning loop.

Should I manually initiate a “Clean Bundles” task and get those new log entries? My server is currently not stuck in the loop, but triggering that task might get it there.

@BigWheel Which of the server logs would be of interest? The whole zipped batch? The zip file is 3.5 MB - I could repackage it with only those files of significance if it would help.

9

it will be in the plex media server.log files. there will be 6 of them 1-5 and an unnumbered one. Number 5 being the oldest. They might have rolled over but you can check if any of them have lines like below

This is what a the log lines look like for clean bundles. ( I only had one thing needing to be cleaned)

Sep 15, 2022 19:15:47.529 [0x16c123000] DEBUG - Request: [192.168.81.12:63212 (Subnet)] PUT /library/clean/bundles?async=1 (27 live) #29a TLS GZIP Signed-in Token (BigWheel) (Chrome)
Sep 15, 2022 19:15:47.530 [0x16c123000] DEBUG - [Req#29a] Activity: registered new activity 2b5f576b-ab59-4db8-ac83-807 - "Cleaning bundles"
Sep 15, 2022 19:15:47.531 [0x16ba93000] DEBUG - Completed: [192.168.81.12:65503] 200 PUT /library/clean/bundles?async=1 (27 live) TLS GZIP 1ms 423 bytes (pipelined: 19)
Sep 15, 2022 19:15:47.531 [0x16b7d7000] DEBUG - Activity: updated activity 2b5f576b-ab59-4db8-ac83-807 - completed 0.0% - Cleaning bundles
Sep 15, 2022 19:15:47.583 [0x16b7d7000] DEBUG - Activity: updated activity 2b5f576b-ab59-4db8-ac83-807 - completed 25.0% - Cleaning bundles
Sep 15, 2022 19:15:47.590 [0x16b7d7000] DEBUG - Activity: updated activity 2b5f576b-ab59-4db8-ac83-807 - completed 50.0% - Cleaning bundles
Sep 15, 2022 19:15:47.590 [0x16b7d7000] DEBUG - Deleted 1 metadata bundles.
Sep 15, 2022 19:15:47.590 [0x16b7d7000] DEBUG - Activity: updated activity 2b5f576b-ab59-4db8-ac83-807 - completed 50.0% - Cleaning bundles
Sep 15, 2022 19:15:47.706 [0x16b7d7000] DEBUG - Activity: updated activity 2b5f576b-ab59-4db8-ac83-807 - completed 75.0% - Cleaning bundles
Sep 15, 2022 19:15:47.710 [0x16b7d7000] DEBUG - Activity: updated activity 2b5f576b-ab59-4db8-ac83-807 - completed 100.0% - Cleaning bundles
Sep 15, 2022 19:15:47.710 [0x16b7d7000] DEBUG - Deleted 1 media bundles.
Sep 15, 2022 19:15:47.710 [0x16b7d7000] DEBUG - Activity: Ended activity 2b5f576b-ab59-4db8-ac83-807
10

Only 1 of my “Plex Media Server.log” files had a Cleaning Bundles entry, it was the *.1.log file and here is the relevant snippet:

Sep 15, 2022 02:09:04.860 [0x6fb89c50] DEBUG - Activity: registered new activity 0b80c7e7-553f-4a49-8167-2ab5d94b22c7 - “Cleaning Bundles”
Sep 15, 2022 02:09:04.878 [0x6fb89c50] DEBUG - Activity: updated activity 0b80c7e7-553f-4a49-8167-2ab5d94b22c7 - completed -1.0% - Cleaning Bundles
Sep 15, 2022 02:09:16.232 [0x6fb89c50] DEBUG - Activity: updated activity 0b80c7e7-553f-4a49-8167-2ab5d94b22c7 - completed 75.0% - Cleaning Bundles

This -1% directly to 75% and stuck is a little alarming, but to this layman there doesn’t appear to be any other useful info surrounding the event.

Here is that snippet in context:

Sep 15, 2022 02:05:53.159 [0x6fb89c50] DEBUG - Butler: optimized your database
Sep 15, 2022 02:05:53.166 [0x6fb89c50] DEBUG - Blob Database: Collecting garbage.
Sep 15, 2022 02:06:13.526 [0x6deadc50] DEBUG - NetworkServiceBrowser: Parsing SSDP schema for http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:06:13.526 [0x6deadc50] DEBUG - [HCl#49d] HTTP requesting GET http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:06:14.456 [0x70ab4c50] WARN - [HttpClient/HCl#49d] HTTP error requesting GET http://192.168.0.254:45514/agent.xml (56, Failure when receiving data from the peer) (Recv failure: Connection reset by peer)
Sep 15, 2022 02:06:14.456 [0x6deadc50] ERROR - SSDP: Error parsing device schema for http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:06:53.529 [0x6deadc50] DEBUG - NetworkServiceBrowser: Parsing SSDP schema for http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:06:53.529 [0x6deadc50] DEBUG - [HCl#49e] HTTP requesting GET http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:06:54.450 [0x70ab4c50] WARN - [HttpClient/HCl#49e] HTTP error requesting GET http://192.168.0.254:45514/agent.xml (56, Failure when receiving data from the peer) (Recv failure: Connection reset by peer)
Sep 15, 2022 02:06:54.450 [0x6deadc50] ERROR - SSDP: Error parsing device schema for http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:07:01.826 [0x6d52fc50] DEBUG - Sync: uploadStatus
Sep 15, 2022 02:07:24.187 [0x6fb89c50] DEBUG - Blob Database: Collected 25 garbage blobs in 91.0 sec.
Sep 15, 2022 02:07:24.187 [0x6fb89c50] DEBUG - Captured session 0.
Sep 15, 2022 02:07:24.187 [0x6fb89c50] DEBUG - Captured session 1.
Sep 15, 2022 02:07:33.532 [0x6deadc50] DEBUG - NetworkServiceBrowser: Parsing SSDP schema for http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:07:33.532 [0x6deadc50] DEBUG - [HCl#49f] HTTP requesting GET http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:07:34.958 [0x70ab4c50] WARN - [HttpClient/HCl#49f] HTTP error requesting GET http://192.168.0.254:45514/agent.xml (56, Failure when receiving data from the peer) (Recv failure: Connection reset by peer)
Sep 15, 2022 02:07:34.959 [0x6deadc50] ERROR - SSDP: Error parsing device schema for http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:07:36.927 [0x7016ec50] DEBUG - PublicAddressManager: Obtaining public address and mapping port.
Sep 15, 2022 02:07:37.276 [0x6d52fc50] DEBUG - PublicAddressManager: Obtaining public IP.
Sep 15, 2022 02:07:37.277 [0x6d52fc50] DEBUG - [HCl#4a0] HTTP requesting GET http://plex.tv/pms/:/ip
Sep 15, 2022 02:07:45.650 [0x70ab4c50] DEBUG - [HttpClient/HCl#4a0] HTTP/2.0 (8.4s) 200 response from GET http://plex.tv/pms/:/ip
Sep 15, 2022 02:07:45.829 [0x6d52fc50] DEBUG - PublicAddressManager: Got public IP from http://plex.tv: 198.84.182.87
Sep 15, 2022 02:07:48.853 [0x6d52fc50] DEBUG - NAT: UPnP, found device <http://192.168.0.1:33799/rootDesc.xml> with private address <192.168.0.13>
Sep 15, 2022 02:07:48.891 [0x6d52fc50] DEBUG - NAT: UPnP, usable device <http://192.168.0.1:33799/rootDesc.xml> with private address <192.168.0.13>.
Sep 15, 2022 02:07:48.919 [0x6d52fc50] DEBUG - NAT: UPnP, public address is 198.84.182.87
Sep 15, 2022 02:07:49.186 [0x6d52fc50] DEBUG - [HCl#4a1] HTTP requesting GET https://198-84-182-87.dbc0e236176647c9a969b012cc6d1daf.plex.direct:32400/identity
Sep 15, 2022 02:07:49.189 [0x70ab4c50] WARN - [HttpClient/HCl#4a1] HTTP error requesting GET https://198-84-182-87.dbc0e236176647c9a969b012cc6d1daf.plex.direct:32400/identity (7, Couldn't connect to server) (Failed to connect to 198-84-182-87.dbc0e236176647c9a969b012cc6d1daf.plex.direct port 32400: Connection refused)
Sep 15, 2022 02:07:49.203 [0x6d52fc50] DEBUG - MyPlex: mapping state set to 'Mapped - Not Published'.
Sep 15, 2022 02:07:49.254 [0x6d52fc50] DEBUG - MyPlex: Last published value didn't change, we're done.
Sep 15, 2022 02:08:13.536 [0x6deadc50] DEBUG - NetworkServiceBrowser: Parsing SSDP schema for http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:08:13.536 [0x6deadc50] DEBUG - [HCl#4a2] HTTP requesting GET http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:08:14.429 [0x70ab4c50] WARN - [HttpClient/HCl#4a2] HTTP error requesting GET http://192.168.0.254:45514/agent.xml (56, Failure when receiving data from the peer) (Recv failure: Connection reset by peer)
Sep 15, 2022 02:08:14.430 [0x6deadc50] ERROR - SSDP: Error parsing device schema for http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:08:53.539 [0x6deadc50] DEBUG - NetworkServiceBrowser: Parsing SSDP schema for http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:08:53.539 [0x6deadc50] DEBUG - [HCl#4a3] HTTP requesting GET http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:08:54.425 [0x70ab4c50] WARN - [HttpClient/HCl#4a3] HTTP error requesting GET http://192.168.0.254:45514/agent.xml (56, Failure when receiving data from the peer) (Recv failure: Connection reset by peer)
Sep 15, 2022 02:08:54.425 [0x6deadc50] ERROR - SSDP: Error parsing device schema for http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:09:02.206 [0x6fb89c50] INFO - SQLITE3:(nil), 17, statement aborts at 58: [select * from metadata_items limit 1] database schema has changed
Sep 15, 2022 02:09:02.785 [0x6fb89c50] DEBUG - It took 20.000000 ms to retrieve 129 items.
Sep 15, 2022 02:09:03.436 [0x6fb89c50] DEBUG - It took 20.000000 ms to retrieve 125 items.
Sep 15, 2022 02:09:04.185 [0x6fb89c50] DEBUG - It took 10.000000 ms to retrieve 137 items.
Sep 15, 2022 02:09:04.368 [0x6fb89c50] DEBUG - It took 20.000000 ms to retrieve 221 items.
Sep 15, 2022 02:09:04.556 [0x6fb89c50] DEBUG - It took 10.000000 ms to retrieve 106 items.
Sep 15, 2022 02:09:04.639 [0x6fb89c50] DEBUG - It took 10.000000 ms to retrieve 115 items.
Sep 15, 2022 02:09:04.860 [0x6fb89c50] DEBUG - Activity: registered new activity 0b80c7e7-553f-4a49-8167-2ab5d94b22c7 - "Cleaning Bundles"
Sep 15, 2022 02:09:04.878 [0x6fb89c50] DEBUG - Activity: updated activity 0b80c7e7-553f-4a49-8167-2ab5d94b22c7 - completed -1.0% - Cleaning Bundles
Sep 15, 2022 02:09:16.232 [0x6fb89c50] DEBUG - Activity: updated activity 0b80c7e7-553f-4a49-8167-2ab5d94b22c7 - completed 75.0% - Cleaning Bundles
Sep 15, 2022 02:09:33.179 [0x6d52fc50] DEBUG - [ViewStateSync] Starting
Sep 15, 2022 02:09:33.184 [0x6d52fc50] DEBUG - [ViewStateSync] Fetching user tokens
Sep 15, 2022 02:09:33.190 [0x6d52fc50] DEBUG - [ViewStateSync/HCl#4a4] HTTP requesting GET https://plex.tv/api/v2/server/users/services?auth_token=xxxxxxxxxxxxxxxxxxxx
Sep 15, 2022 02:09:33.541 [0x6deadc50] DEBUG - NetworkServiceBrowser: Parsing SSDP schema for http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:09:33.541 [0x6deadc50] DEBUG - [HCl#4a5] HTTP requesting GET http://192.168.0.254:45514/agent.xml
Sep 15, 2022 02:09:33.715 [0x70ab4c50] DEBUG - [HttpClient/HCl#4a4] HTTP/2.0 (0.5s) 200 response from GET https://plex.tv/api/v2/server/users/services?auth_token=xxxxxxxxxxxxxxxxxxxx
Sep 15, 2022 02:09:33.744 [0x6ebe5c50] DEBUG - [ViewStateSync] Got token for user 1 (The1Grenade)

Please let me know if you would like the full log file(s) or if I should trigger a fresh cleaning to capture new logs.

11

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