Plex Music library won't find newly added content

Plex Media Server Metadata & Adding Files
,
1

PMS: 1.26.2.5797 and 1.27.1.5916
System: Docker using the official image
Plex Pass: Yes

Plex Music library won’t find newly added content and some content that was previously found is not added to a newly setup music library. I’m using the Plex Music scanner. It’s been working fine up to now. Logs show, Error parsing content, Error parsing XML: Error parsing file.. If I change to the legacy scanner, the content is found. Anyone experienced anything similar or have any suggestions?

Things I’ve tried;

  • Checked naming conventions
  • Checked permissions. All files are owned by the UID and PID mapped to the Plex container
  • Set permissions to 777 just to test
  • Plex dance
  • Updated to latest PMS
  • Updated to Beta branch
  • Fresh Plex install
  • Fresh Plex install using Linuxserver image instead of original
  • Moved my music to a brand new hard drive

This is driving me nuts! Any help or advice appreciated.

Heres a short log excerpt showing the error;

Jun 27, 2022 23:38:03.854 [0x7f5ed5279b38] Debug — Signalling job ID 13689 with 9
Jun 27, 2022 23:38:03.854 [0x7f5ed5279b38] Debug — Native Scanner: Executed Match stage in 0.15 sec.
Jun 27, 2022 23:38:03.854 [0x7f5ed5279b38] Debug — Native Scanner: Executed Add to Database stage in 0.00 sec.
Jun 27, 2022 23:38:03.854 [0x7f5ed5279b38] Debug — Native Scanner: Executed Media Analysis stage in 0.00 sec.
Jun 27, 2022 23:38:03.854 [0x7f5ed5279b38] Debug — [JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/config/Library/Application\ Support/Plex\ Media\ Server/Codecs/d53cb63-4323-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx "/usr/lib/plexmediaserver/Plex Media Scanner" --match --type 8 --log-file-suffix " Matcher"
Jun 27, 2022 23:38:03.855 [0x7f5ed577eb38] Debug — Activity: updated activity 6a39947b-42b7-4c07-93d4-a046124e36e5 - completed 79.6% - Scanning Music Test
Jun 27, 2022 23:38:03.855 [0x7f5ed577eb38] Debug — Scanner: Processing directory /htpc10/Media/Music/The Chemical Brothers/Surrender (parent: yes)
Jun 27, 2022 23:38:03.855 [0x7f5ed5279b38] Debug — [JobRunner] Jobs: Starting child process with pid 13692
Jun 27, 2022 23:38:03.855 [0x7f5ed577eb38] Verbose —     * Noting that 'The Chemical Brothers/Surrender' was updated at 2020-08-09 12:06:47
Jun 27, 2022 23:38:03.855 [0x7f5ed577eb38] Verbose —     * Taking directory 'The Chemical Brothers/Surrender' (21631) out of the map (0 left)
Jun 27, 2022 23:38:03.855 [0x7f5ed577eb38] Verbose — Adding file for scanner: "/htpc10/Media/Music/The Chemical Brothers/Surrender/01 - Music- Response.flac"
Jun 27, 2022 23:38:03.855 [0x7f5ed577eb38] Verbose — Adding file for scanner: "/htpc10/Media/Music/The Chemical Brothers/Surrender/02 - Under the Influence.flac"
Jun 27, 2022 23:38:03.855 [0x7f5ed577eb38] Verbose — Adding file for scanner: "/htpc10/Media/Music/The Chemical Brothers/Surrender/03 - Out of Control.flac"
Jun 27, 2022 23:38:03.855 [0x7f5ed577eb38] Verbose — Adding file for scanner: "/htpc10/Media/Music/The Chemical Brothers/Surrender/04 - Orange Wedge.flac"
Jun 27, 2022 23:38:03.856 [0x7f5ed577eb38] Verbose — Adding file for scanner: "/htpc10/Media/Music/The Chemical Brothers/Surrender/05 - Let Forever Be.flac"
Jun 27, 2022 23:38:03.856 [0x7f5ed577eb38] Verbose — Adding file for scanner: "/htpc10/Media/Music/The Chemical Brothers/Surrender/06 - The Sunshine Underground.flac"
Jun 27, 2022 23:38:03.856 [0x7f5ed577eb38] Verbose — Adding file for scanner: "/htpc10/Media/Music/The Chemical Brothers/Surrender/07 - Asleep From Day.flac"
Jun 27, 2022 23:38:03.856 [0x7f5ed577eb38] Verbose — Adding file for scanner: "/htpc10/Media/Music/The Chemical Brothers/Surrender/08 - Got Glint.flac"
Jun 27, 2022 23:38:03.856 [0x7f5ed577eb38] Verbose — Adding file for scanner: "/htpc10/Media/Music/The Chemical Brothers/Surrender/09 - Hey Boy Hey Girl.flac"
Jun 27, 2022 23:38:03.856 [0x7f5ed577eb38] Verbose — Adding file for scanner: "/htpc10/Media/Music/The Chemical Brothers/Surrender/09 - Hey Boy Hey Girl.lrc"
Jun 27, 2022 23:38:03.856 [0x7f5ed577eb38] Verbose — Adding file for scanner: "/htpc10/Media/Music/The Chemical Brothers/Surrender/10 - Surrender.flac"
Jun 27, 2022 23:38:03.856 [0x7f5ed577eb38] Verbose — Adding file for scanner: "/htpc10/Media/Music/The Chemical Brothers/Surrender/11 - Dream On.flac"
Jun 27, 2022 23:38:03.856 [0x7f5ed577eb38] Debug — Directory had 11 files, database had 0 files, can't skip.
Jun 27, 2022 23:38:03.857 [0x7f5ed9017b38] Verbose — JobManager: child process with handle 13689 exited
Jun 27, 2022 23:38:03.857 [0x7f5ed9017b38] Debug — Jobs: '/usr/lib/plexmediaserver/Plex Media Scanner' exit code for process 13689 is 0 (success)
Jun 27, 2022 23:38:04.017 [0x7f5ed5279b38] Error — Error parsing content.
Jun 27, 2022 23:38:04.017 [0x7f5ed5279b38] Error — Error parsing XML: Error parsing file.
Jun 27, 2022 23:38:04.017 [0x7f5ed5279b38] Debug — Killing job.
Jun 27, 2022 23:38:04.017 [0x7f5ed5279b38] Debug — Signalling job ID 13692 with 9
Jun 27, 2022 23:38:04.017 [0x7f5ed5279b38] Debug — Native Scanner: Executed Match stage in 0.16 sec.
Jun 27, 2022 23:38:04.017 [0x7f5ed4faab38] Debug — Native Scanner: Executed Add to Database stage in 0.00 sec.
Jun 27, 2022 23:38:04.017 [0x7f5ed4faab38] Debug — Native Scanner: Executed Media Analysis stage in 0.00 sec.
Jun 27, 2022 23:38:04.017 [0x7f5ed9017b38] Verbose — JobManager: child process with handle 13692 exited
1 Like
2

Could be the files are recognized as something else due to the extra folder layer. Plex might be considering the CD 02 folder to refer to the actual album – no its parent folders.

3

Thanks for the help. This is just one of many that aren’t added, most don’t follow the CD1/2 pattern. Just to confirm though, I removed the CD1/2 folders and placed the files in the Album root folder and Plex still didn’t add them. I’ve edited my post to show the logs from a single disc album just to avoid confusion. Thanks again though.

4

Please turn off verbose logging and post your entire server logs and we can see what is going on. Thanks

5

Thanks. Please see the logs with Verbose off. These are the logs for adding a single Artist folder. Plex finds the 6 albums but doesn’t add any to the Library.

Jun 28, 2022 09:52:10.278 [0x7f36dabf1b38] Info — Request: [192.168.0.2:51809 (Allowed Network (WAN))] POST /library/sections?name=Music%20Test&type=artist&agent=tv.plex.agents.music&scanner=Plex%20Music&language=en&importFromiTunes=&enableAutoPhotoTags=&downloadMedia=&location=%2Fhtpc08%2FMedia%2FMusic%2FGrimes (11 live) TLS GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:10.291 [0x7f36dabf1b38] Debug — Flushing directory modification time cache.
Jun 28, 2022 09:52:10.296 [0x7f36dadb5b38] Debug — MyPlex: sendMapping resetting state - previous mapping state: 'Mapped - Not Published (Not Reachable)'.
Jun 28, 2022 09:52:10.296 [0x7f36dadb5b38] Debug — MyPlex: mapping state set to 'Unknown'.
Jun 28, 2022 09:52:10.307 [0x7f36dabf1b38] Debug — Library Updater: Requested that section 2 be updated, force=0, deep=0, subdir= iTunes=0
Jun 28, 2022 09:52:10.307 [0x7f36dabf1b38] Debug — Library Updater: Queueing section 2
Jun 28, 2022 09:52:10.307 [0x7f36dabf1b38] Info — Refreshing paths watched by LibraryUpdateManager
Jun 28, 2022 09:52:10.309 [0x7f36dad65b38] Debug — Activity: registered new activity b955aaf4-e35f-46f0-8871-f7ed14f81697 - "Scanning"
Jun 28, 2022 09:52:10.309 [0x7f36dad65b38] Debug — Scanning section 2
Jun 28, 2022 09:52:10.310 [0x7f36dadb5b38] Debug — MyPlex: Sending Server Info to myPlex (user=xxxxxxxxxx, ip=, port=0)
Jun 28, 2022 09:52:10.310 [0x7f36dadb5b38] Debug — HTTP requesting POST https://plex.tv/servers.xml?auth_token=xxxxxxxxxxxxxxxxxxxx
Jun 28, 2022 09:52:10.315 [0x7f36dad65b38] Debug — Activity: updated activity b955aaf4-e35f-46f0-8871-f7ed14f81697 - completed 0.0% - Scanning Music Test
Jun 28, 2022 09:52:10.318 [0x7f36dad65b38] Debug — Asked to cull library timeline before time 1656405130, we're starting with 0 items.
Jun 28, 2022 09:52:10.318 [0x7f36dad65b38] Debug — Library timeline cull complete with 0 items left.
Jun 28, 2022 09:52:10.321 [0x7f36dad65b38] Debug — Scanning Music Test using en(Plex Music) with 0 current media items and 1 section locations in the database.
Jun 28, 2022 09:52:10.321 [0x7f36dad65b38] Debug — Performing a scan with 'Plex Music' (language: en virtual: 0).
Jun 28, 2022 09:52:10.321 [0x7f36dad65b38] Debug —   * Scanning /htpc08/Media/Music/Grimes

Jun 28, 2022 09:52:10.322 [0x7f36dad65b38] Debug — Scanner: Processing directory /htpc08/Media/Music/Grimes (parent: no)
Jun 28, 2022 09:52:10.326 [0x7f36dad65b38] Debug — Scanner: Processing directory /htpc08/Media/Music/Grimes/Geidi Primes (parent: yes)
Jun 28, 2022 09:52:10.327 [0x7f36db4b6b38] Info — Completed: [192.168.0.2:51809] 201 POST /library/sections?name=Music%20Test&type=artist&agent=tv.plex.agents.music&scanner=Plex%20Music&language=en&importFromiTunes=&enableAutoPhotoTags=&downloadMedia=&location=%2Fhtpc08%2FMedia%2FMusic%2FGrimes (11 live) TLS GZIP 48ms 821 bytes (pipelined: 26)
Jun 28, 2022 09:52:10.329 [0x7f36dad65b38] Debug — Directory had 11 files, database had 0 files, can't skip.
Jun 28, 2022 09:52:10.330 [0x7f36dad65b38] Debug — Activity: updated activity b955aaf4-e35f-46f0-8871-f7ed14f81697 - completed 16.5% - Scanning Music Test
Jun 28, 2022 09:52:10.330 [0x7f36dad65b38] Debug — Scanner: Processing directory /htpc08/Media/Music/Grimes/Halfaxa (parent: yes)
Jun 28, 2022 09:52:10.331 [0x7f36dad65b38] Debug — Directory had 14 files, database had 0 files, can't skip.
Jun 28, 2022 09:52:10.336 [0x7f36dabf1b38] Debug — Request: [192.168.0.2:51809 (Allowed Network (WAN))] GET /library/sections (11 live) TLS GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:10.337 [0x7f36db4d9b38] Debug — Completed: [192.168.0.2:51809] 200 GET /library/sections (11 live) TLS GZIP 0ms 798 bytes (pipelined: 27)
Jun 28, 2022 09:52:10.356 [0x7f36dabf1b38] Debug — Request: [192.168.0.2:51809 (Allowed Network (WAN))] GET /library/sections (11 live) TLS GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:10.357 [0x7f36db4d9b38] Debug — Completed: [192.168.0.2:51809] 200 GET /library/sections (11 live) TLS GZIP 0ms 798 bytes (pipelined: 28)
Jun 28, 2022 09:52:10.361 [0x7f36dabf1b38] Debug — Request: [192.168.0.2:51838 (Allowed Network (WAN))] GET /media/providers (11 live) TLS GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:10.363 [0x7f36db4b6b38] Debug — Completed: [192.168.0.2:51838] 200 GET /media/providers (11 live) TLS GZIP 2ms 4641 bytes (pipelined: 9)
Jun 28, 2022 09:52:10.372 [0x7f36db253b38] Debug — [HttpClient] HTTP/2.0 (0.1s) 422 response from POST https://plex.tv/servers.xml?auth_token=xxxxxxxxxxxxxxxxxxxx (reused)
Jun 28, 2022 09:52:10.373 [0x7f36dadb5b38] Debug — MyPlex: Published Mapping State response was 422
Jun 28, 2022 09:52:10.373 [0x7f36dadb5b38] Debug — MyPlex: Got response for e7209c43736d8f3c7afa04ba72c93578d86744d9 ~ registered :0
Jun 28, 2022 09:52:10.373 [0x7f36dadb5b38] Debug — MyPlex: updating mapped state - current state: 'Mapped - Not Published (Not Reachable)'
Jun 28, 2022 09:52:10.373 [0x7f36dadb5b38] Debug — MyPlex: mapping state set to 'Mapped - Publishing'.
Jun 28, 2022 09:52:10.373 [0x7f36dadb5b38] Debug — MyPlex: async reachability check - current mapped state: 'Mapped - Publishing'.
Jun 28, 2022 09:52:10.373 [0x7f36dadb5b38] Debug — MyPlex: Requesting reachability check.
Jun 28, 2022 09:52:10.373 [0x7f36dadb5b38] Debug — HTTP requesting PUT https://plex.tv/api/servers/e7209c43736d8f3c7afa04ba72c93578d86744d9/connectivity?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx&asyncIdentifier=dbf9d332-74e3-4ef9-9d99-6942410fd287
Jun 28, 2022 09:52:10.388 [0x7f36dac47b38] Debug — [JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/config/Library/Application\ Support/Plex\ Media\ Server/Codecs/d53cb63-4323-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx "/usr/lib/plexmediaserver/Plex Media Scanner" --match --type 8 --log-file-suffix " Matcher"
Jun 28, 2022 09:52:10.389 [0x7f36dac47b38] Debug — [JobRunner] Jobs: Starting child process with pid 609
Jun 28, 2022 09:52:10.402 [0x7f36dabf1b38] Debug — Request: [192.168.0.2:51809 (Allowed Network (WAN))] GET /media/providers (11 live) TLS GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:10.404 [0x7f36db4b6b38] Debug — Completed: [192.168.0.2:51809] 200 GET /media/providers (11 live) TLS GZIP 1ms 4640 bytes (pipelined: 29)
Jun 28, 2022 09:52:10.410 [0x7f36dabf1b38] Debug — Request: [192.168.0.2:51838 (Allowed Network (WAN))] GET /media/providers (11 live) TLS GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:10.411 [0x7f36db253b38] Debug — [HttpClient] HTTP/2.0 (0.0s) 200 response from PUT https://plex.tv/api/servers/e7209c43736d8f3c7afa04ba72c93578d86744d9/connectivity?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx&asyncIdentifier=dbf9d332-74e3-4ef9-9d99-6942410fd287 (reused)
Jun 28, 2022 09:52:10.411 [0x7f36dadb5b38] Debug — HTTP requesting GET https://plex.tv/api/v2/server/access_tokens?auth_token=xxxxxxxxxxxxxxxxxxxx
Jun 28, 2022 09:52:10.412 [0x7f36db4d9b38] Debug — Completed: [192.168.0.2:51838] 200 GET /media/providers (11 live) TLS GZIP 2ms 4640 bytes (pipelined: 10)
Jun 28, 2022 09:52:10.433 [0x7f36db4b6b38] Debug — [EventSourceClient/pubsub/109.237.24.233:443] EventSource: Got event [data] '<Message command="notifyFavoritesChange"/>'
Jun 28, 2022 09:52:10.435 [0x7f36db4b6b38] Debug — Using X-Forwarded-For: 2.216.126.13 as remote address
Jun 28, 2022 09:52:10.435 [0x7f36dabf1b38] Debug — Request: [192.168.90.254:56350 (WAN)] GET /media/providers (11 live) GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:10.438 [0x7f36db4b6b38] Debug — Completed: [192.168.90.254:56350] 200 GET /media/providers (11 live) GZIP 2ms 4640 bytes (pipelined: 2)
Jun 28, 2022 09:52:10.442 [0x7f36db4b6b38] Debug — [EventSourceClient/pubsub/109.237.24.233:443] EventSource: Got event [data] '<Message address="" port="0" asyncIdentifier="dbf9d332-74e3-4ef9-9d99-6942410fd287" connectivity="0" command="notifyConnectivity"/>'
Jun 28, 2022 09:52:10.442 [0x7f36db4b6b38] Debug — [EventSourceClient/pubsub/109.237.24.233:443] PubSub: Got notified of reachability for async identifier dbf9d332-74e3-4ef9-9d99-6942410fd287: 0 for :0 (responded in 31 ms)
Jun 28, 2022 09:52:10.442 [0x7f36db4b6b38] Debug — [EventSourceClient/pubsub/109.237.24.233:443] MyPlex: reachability check - current mapping state: 'Mapped - Publishing'.
Jun 28, 2022 09:52:10.442 [0x7f36db4b6b38] Debug — [EventSourceClient/pubsub/109.237.24.233:443] MyPlex: mapping state set to 'Mapped - Not Published (Not Reachable)'.
Jun 28, 2022 09:52:10.455 [0x7f36db253b38] Debug — [HttpClient] HTTP/2.0 (0.0s) 200 response from GET https://plex.tv/api/v2/server/access_tokens?auth_token=xxxxxxxxxxxxxxxxxxxx (reused)
Jun 28, 2022 09:52:10.456 [0x7f36dadb5b38] Debug — MyPlex: updating with 28 access tokens
Jun 28, 2022 09:52:10.457 [0x7f36dadb5b38] Debug — HTTP requesting GET https://plex.tv/api/v2/server/users?auth_token=xxxxxxxxxxxxxxxxxxxx
Jun 28, 2022 09:52:10.458 [0x7f36da967b38] Debug — [MediaProviderManager] HTTP requesting GET https://plex.tv/media/providers?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx
Jun 28, 2022 09:52:10.475 [0x7f36dabf1b38] Debug — Request: [192.168.0.2:51809 (Allowed Network (WAN))] GET /myplex/account (11 live) TLS GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:10.476 [0x7f36db4d9b38] Debug — Completed: [192.168.0.2:51809] 200 GET /myplex/account (11 live) TLS GZIP 1ms 3569 bytes (pipelined: 30)
Jun 28, 2022 09:52:10.493 [0x7f36db253b38] Debug — [HttpClient] HTTP/2.0 (0.0s) 200 response from GET https://plex.tv/media/providers?X-Plex-Token=xxxxxxxxxxxxxxxxxxxx (reused)
Jun 28, 2022 09:52:10.493 [0x7f36db253b38] Debug — [HttpClient] HTTP/2.0 (0.0s) 200 response from GET https://plex.tv/api/v2/server/users?auth_token=xxxxxxxxxxxxxxxxxxxx (reused)
Jun 28, 2022 09:52:10.493 [0x7f36da967b38] Debug — [MediaProviderManager] discovered cloud provider (Metadata)
Jun 28, 2022 09:52:10.494 [0x7f36da98ab38] Debug — HTTP requesting GET https://plex.tv/api/v2/server/users/subscriptions?auth_token=xxxxxxxxxxxxxxxxxxxx
Jun 28, 2022 09:52:10.497 [0x7f36da967b38] Debug — [MediaProviderManager] loading cloud provider details (Metadata) (alive: 1)
Jun 28, 2022 09:52:10.497 [0x7f36da967b38] Debug — [MediaProviderManager] we had 1 cloud providers online, we now have 1
Jun 28, 2022 09:52:10.497 [0x7f36da967b38] Debug — [MediaProviderManager] cloud provider (Metadata) is online and available
Jun 28, 2022 09:52:10.510 [0x7f36db4b6b38] Debug — Using X-Forwarded-For: 2.216.126.13 as remote address
Jun 28, 2022 09:52:10.510 [0x7f36dabf1b38] Debug — Request: [192.168.90.254:56350 (WAN)] GET /media/providers (11 live) GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:10.512 [0x7f36db4d9b38] Debug — Completed: [192.168.90.254:56350] 200 GET /media/providers (11 live) GZIP 2ms 4640 bytes (pipelined: 3)
Jun 28, 2022 09:52:10.514 [0x7f36dabf1b38] Debug — Request: [192.168.0.2:51809 (Allowed Network (WAN))] GET /myplex/account (11 live) TLS GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:10.515 [0x7f36db4b6b38] Debug — Completed: [192.168.0.2:51809] 200 GET /myplex/account (11 live) TLS GZIP 1ms 3569 bytes (pipelined: 31)
Jun 28, 2022 09:52:10.530 [0x7f36db253b38] Debug — [HttpClient] HTTP/2.0 (0.0s) 200 response from GET https://plex.tv/api/v2/server/users/subscriptions?auth_token=xxxxxxxxxxxxxxxxxxxx (reused)
Jun 28, 2022 09:52:10.530 [0x7f36da9f3b38] Debug — HTTP requesting GET https://plex.tv/api/v2/server/users/services?auth_token=xxxxxxxxxxxxxxxxxxxx
Jun 28, 2022 09:52:10.569 [0x7f36db253b38] Debug — [HttpClient] HTTP/2.0 (0.0s) 200 response from GET https://plex.tv/api/v2/server/users/services?auth_token=xxxxxxxxxxxxxxxxxxxx (reused)
Jun 28, 2022 09:52:10.738 [0x7f36dac47b38] Error — Error parsing content.
Jun 28, 2022 09:52:10.738 [0x7f36dbda0b38] Debug — Jobs: '/usr/lib/plexmediaserver/Plex Media Scanner' exit code for process 609 is 0 (success)
Jun 28, 2022 09:52:10.749 [0x7f36dac47b38] Error — Error parsing XML: Error parsing file.
Jun 28, 2022 09:52:10.749 [0x7f36dac47b38] Debug — Native Scanner: Executed Match stage in 0.42 sec.
Jun 28, 2022 09:52:10.749 [0x7f36dac47b38] Debug — Native Scanner: Executed Add to Database stage in 0.00 sec.
Jun 28, 2022 09:52:10.749 [0x7f36dac47b38] Debug — Native Scanner: Executed Media Analysis stage in 0.00 sec.
Jun 28, 2022 09:52:10.749 [0x7f36dad65b38] Debug — Activity: updated activity b955aaf4-e35f-46f0-8871-f7ed14f81697 - completed 33.0% - Scanning Music Test
Jun 28, 2022 09:52:10.750 [0x7f36dad65b38] Debug — Scanner: Processing directory /htpc08/Media/Music/Grimes/Darkbloom (parent: yes)
Jun 28, 2022 09:52:10.750 [0x7f36da904b38] Debug — [JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/config/Library/Application\ Support/Plex\ Media\ Server/Codecs/d53cb63-4323-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx "/usr/lib/plexmediaserver/Plex Media Scanner" --match --type 8 --log-file-suffix " Matcher"
Jun 28, 2022 09:52:10.751 [0x7f36dad65b38] Debug — Directory had 5 files, database had 0 files, can't skip.
Jun 28, 2022 09:52:10.755 [0x7f36da904b38] Debug — [JobRunner] Jobs: Starting child process with pid 614
Jun 28, 2022 09:52:10.882 [0x7f36da904b38] Error — Error parsing content.
Jun 28, 2022 09:52:10.882 [0x7f36dbda0b38] Debug — Jobs: '/usr/lib/plexmediaserver/Plex Media Scanner' exit code for process 614 is 0 (success)
Jun 28, 2022 09:52:10.882 [0x7f36da904b38] Error — Error parsing XML: Error parsing file.
Jun 28, 2022 09:52:10.882 [0x7f36da904b38] Debug — Native Scanner: Executed Match stage in 0.13 sec.
Jun 28, 2022 09:52:10.882 [0x7f36dac47b38] Debug — Native Scanner: Executed Add to Database stage in 0.00 sec.
Jun 28, 2022 09:52:10.882 [0x7f36dac47b38] Debug — Native Scanner: Executed Media Analysis stage in 0.00 sec.
Jun 28, 2022 09:52:10.883 [0x7f36dad65b38] Debug — Activity: updated activity b955aaf4-e35f-46f0-8871-f7ed14f81697 - completed 49.5% - Scanning Music Test
Jun 28, 2022 09:52:10.883 [0x7f36dad65b38] Debug — Scanner: Processing directory /htpc08/Media/Music/Grimes/Visions (parent: yes)
Jun 28, 2022 09:52:10.884 [0x7f36dac47b38] Debug — [JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/config/Library/Application\ Support/Plex\ Media\ Server/Codecs/d53cb63-4323-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx "/usr/lib/plexmediaserver/Plex Media Scanner" --match --type 8 --log-file-suffix " Matcher"
Jun 28, 2022 09:52:10.885 [0x7f36dac47b38] Debug — [JobRunner] Jobs: Starting child process with pid 617
Jun 28, 2022 09:52:10.887 [0x7f36dad65b38] Debug — Directory had 13 files, database had 0 files, can't skip.
Jun 28, 2022 09:52:11.130 [0x7f36dac47b38] Error — Error parsing content.
Jun 28, 2022 09:52:11.130 [0x7f36dac47b38] Error — Error parsing XML: Error parsing file.
Jun 28, 2022 09:52:11.130 [0x7f36dac47b38] Debug — Killing job.
Jun 28, 2022 09:52:11.130 [0x7f36dac47b38] Debug — Signalling job ID 617 with 9
Jun 28, 2022 09:52:11.130 [0x7f36dac47b38] Debug — Native Scanner: Executed Match stage in 0.25 sec.
Jun 28, 2022 09:52:11.130 [0x7f36dac47b38] Debug — Native Scanner: Executed Add to Database stage in 0.00 sec.
Jun 28, 2022 09:52:11.130 [0x7f36dac47b38] Debug — Native Scanner: Executed Media Analysis stage in 0.00 sec.
Jun 28, 2022 09:52:11.131 [0x7f36dad65b38] Debug — Activity: updated activity b955aaf4-e35f-46f0-8871-f7ed14f81697 - completed 66.0% - Scanning Music Test
Jun 28, 2022 09:52:11.131 [0x7f36dad65b38] Debug — Scanner: Processing directory /htpc08/Media/Music/Grimes/Art Angels (parent: yes)
Jun 28, 2022 09:52:11.132 [0x7f36dac47b38] Debug — [JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/config/Library/Application\ Support/Plex\ Media\ Server/Codecs/d53cb63-4323-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx "/usr/lib/plexmediaserver/Plex Media Scanner" --match --type 8 --log-file-suffix " Matcher"
Jun 28, 2022 09:52:11.132 [0x7f36dac47b38] Debug — [JobRunner] Jobs: Starting child process with pid 620
Jun 28, 2022 09:52:11.133 [0x7f36dad65b38] Debug — Directory had 14 files, database had 0 files, can't skip.
Jun 28, 2022 09:52:11.135 [0x7f36dbda0b38] Debug — Jobs: '/usr/lib/plexmediaserver/Plex Media Scanner' exit code for process 617 is 0 (success)
Jun 28, 2022 09:52:11.332 [0x7f36dac47b38] Error — Error parsing content.
Jun 28, 2022 09:52:11.332 [0x7f36dac47b38] Error — Error parsing XML: Error parsing file.
Jun 28, 2022 09:52:11.332 [0x7f36dac47b38] Debug — Killing job.
Jun 28, 2022 09:52:11.332 [0x7f36dac47b38] Debug — Signalling job ID 620 with 9
Jun 28, 2022 09:52:11.332 [0x7f36dac47b38] Debug — Native Scanner: Executed Match stage in 0.20 sec.
Jun 28, 2022 09:52:11.332 [0x7f36dac47b38] Debug — Native Scanner: Executed Add to Database stage in 0.00 sec.
Jun 28, 2022 09:52:11.332 [0x7f36dac47b38] Debug — Native Scanner: Executed Media Analysis stage in 0.00 sec.
Jun 28, 2022 09:52:11.332 [0x7f36dbda0b38] Debug — Jobs: '/usr/lib/plexmediaserver/Plex Media Scanner' exit code for process 620 is 0 (success)
Jun 28, 2022 09:52:11.333 [0x7f36dac47b38] Debug — [JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/config/Library/Application\ Support/Plex\ Media\ Server/Codecs/d53cb63-4323-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx "/usr/lib/plexmediaserver/Plex Media Scanner" --match --type 8 --log-file-suffix " Matcher"
Jun 28, 2022 09:52:11.333 [0x7f36dad65b38] Debug — Activity: updated activity b955aaf4-e35f-46f0-8871-f7ed14f81697 - completed 82.5% - Scanning Music Test
Jun 28, 2022 09:52:11.333 [0x7f36dad65b38] Debug — Scanner: Processing directory /htpc08/Media/Music/Grimes/Miss Anthropocene (parent: yes)
Jun 28, 2022 09:52:11.334 [0x7f36dac47b38] Debug — [JobRunner] Jobs: Starting child process with pid 623
Jun 28, 2022 09:52:11.336 [0x7f36dad65b38] Debug — Directory had 10 files, database had 0 files, can't skip.
Jun 28, 2022 09:52:11.467 [0x7f36dac47b38] Error — Error parsing content.
Jun 28, 2022 09:52:11.467 [0x7f36dbda0b38] Debug — Jobs: '/usr/lib/plexmediaserver/Plex Media Scanner' exit code for process 623 is 0 (success)
Jun 28, 2022 09:52:11.467 [0x7f36dac47b38] Error — Error parsing XML: Error parsing file.
Jun 28, 2022 09:52:11.467 [0x7f36dac47b38] Debug — Native Scanner: Executed Match stage in 0.13 sec.
Jun 28, 2022 09:52:11.467 [0x7f36dac47b38] Debug — Native Scanner: Executed Add to Database stage in 0.00 sec.
Jun 28, 2022 09:52:11.467 [0x7f36dac47b38] Debug — Native Scanner: Executed Media Analysis stage in 0.00 sec.
Jun 28, 2022 09:52:11.467 [0x7f36dad65b38] Debug — Activity: updated activity b955aaf4-e35f-46f0-8871-f7ed14f81697 - completed 99.0% - Scanning Music Test
Jun 28, 2022 09:52:11.467 [0x7f36dac47b38] Debug — [JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/config/Library/Application\ Support/Plex\ Media\ Server/Codecs/d53cb63-4323-linux-x86_64/' X_PLEX_TOKEN=xxxxxxxxxxxxxxxxxxxx "/usr/lib/plexmediaserver/Plex Media Scanner" --match --type 8 --log-file-suffix " Matcher"
Jun 28, 2022 09:52:11.468 [0x7f36dac47b38] Debug — [JobRunner] Jobs: Starting child process with pid 626
Jun 28, 2022 09:52:11.595 [0x7f36dac47b38] Error — Error parsing content.
Jun 28, 2022 09:52:11.595 [0x7f36dbda0b38] Debug — Jobs: '/usr/lib/plexmediaserver/Plex Media Scanner' exit code for process 626 is 0 (success)
Jun 28, 2022 09:52:11.595 [0x7f36dac47b38] Error — Error parsing XML: Error parsing file.
Jun 28, 2022 09:52:11.595 [0x7f36dac47b38] Debug — Native Scanner: Executed Match stage in 0.13 sec.
Jun 28, 2022 09:52:11.595 [0x7f36dac47b38] Debug — Native Scanner: Executed Add to Database stage in 0.00 sec.
Jun 28, 2022 09:52:11.595 [0x7f36dac47b38] Debug — Native Scanner: Executed Media Analysis stage in 0.00 sec.
Jun 28, 2022 09:52:11.595 [0x7f36dad65b38] Debug — Scanner [Plex Music]: Idle and left with 0 media items.
Jun 28, 2022 09:52:11.595 [0x7f36dad65b38] Debug — Removing 0 media items that were left.
Jun 28, 2022 09:52:11.595 [0x7f36dad65b38] Debug — Removing 0 directories that were left.
Jun 28, 2022 09:52:11.595 [0x7f36dad65b38] Debug — Updating directory '' (ID 4084) to time 2020-08-14 01:23:50.
Jun 28, 2022 09:52:11.597 [0x7f36dad65b38] Debug — Updating directory 'Art Angels' (ID 4089) to time 2020-08-13 23:18:52.
Jun 28, 2022 09:52:11.597 [0x7f36dad65b38] Debug — Updating directory 'Darkbloom' (ID 4087) to time 2020-08-14 00:56:10.
Jun 28, 2022 09:52:11.598 [0x7f36dad65b38] Debug — Updating directory 'Geidi Primes' (ID 4085) to time 2020-08-14 01:23:52.
Jun 28, 2022 09:52:11.598 [0x7f36dad65b38] Debug — Updating directory 'Halfaxa' (ID 4086) to time 2020-08-14 01:06:39.
Jun 28, 2022 09:52:11.598 [0x7f36dad65b38] Debug — Updating directory 'Miss Anthropocene' (ID 4090) to time 2020-07-20 00:35:56.
Jun 28, 2022 09:52:11.598 [0x7f36dad65b38] Debug — Updating directory 'Visions' (ID 4088) to time 2020-08-14 00:39:21.
Jun 28, 2022 09:52:11.601 [0x7f36dad65b38] Debug — Collections: Found 0 collections tags in section 2.
Jun 28, 2022 09:52:11.601 [0x7f36dad65b38] Debug — Collections: We had 0 collections in the library already.
Jun 28, 2022 09:52:11.601 [0x7f36dad65b38] Debug — Collections: Synced tags in section 2 in 2ms.
Jun 28, 2022 09:52:11.601 [0x7f36dad65b38] Debug — Collections: Found 0 collections tags in section 2.
Jun 28, 2022 09:52:11.601 [0x7f36dad65b38] Debug — Collections: We had 0 collections in the library already.
Jun 28, 2022 09:52:11.601 [0x7f36dad65b38] Debug — Collections: Synced tags in section 2 in 2ms.
Jun 28, 2022 09:52:11.601 [0x7f36dad65b38] Debug — Collections: Found 0 collections tags in section 2.
Jun 28, 2022 09:52:11.601 [0x7f36dad65b38] Debug — Collections: We had 0 collections in the library already.
Jun 28, 2022 09:52:11.601 [0x7f36dad65b38] Debug — Collections: Synced tags in section 2 in 2ms.
Jun 28, 2022 09:52:11.604 [0x7f36dad65b38] Debug — Collections: Refreshed attributes for 0 collections in section 2 in 2ms.
Jun 28, 2022 09:52:11.605 [0x7f36dad65b38] Debug — Collection: Refreshed visibility in section 2 in 0ms.
Jun 28, 2022 09:52:11.606 [0x7f36dad65b38] Debug — Collections: Refreshed attributes for 0 collections in section 2 in 1ms.
Jun 28, 2022 09:52:11.608 [0x7f36dad65b38] Debug — Activity: updated activity b955aaf4-e35f-46f0-8871-f7ed14f81697 - completed 100.0% - Scanning Music Test
Jun 28, 2022 09:52:11.608 [0x7f36dad65b38] Debug — Refreshing section 2 of type: 8
Jun 28, 2022 09:52:11.609 [0x7f36da863b38] Debug — Refreshing 0 IDs.
Jun 28, 2022 09:52:11.611 [0x7f36dad65b38] Debug — Activity: registered new activity 22c2557f-445d-40ae-bed8-7cf9c26d6c4d - "Processing subscriptions"
Jun 28, 2022 09:52:11.613 [0x7f36dad65b38] Debug — Activity: Ended activity b955aaf4-e35f-46f0-8871-f7ed14f81697.
Jun 28, 2022 09:52:11.614 [0x7f36da967b38] Debug — Grabber: Cleaning up orphaned grabs.
Jun 28, 2022 09:52:11.614 [0x7f36da967b38] Debug — Grabber: Cleaned up 0 decrepit directories in 0.0 sec.
Jun 28, 2022 09:52:11.615 [0x7f36da967b38] Debug — Activity: registered new activity 7ff6fa2c-2bc8-4393-bd3e-1b533ed71e45 - "Processing subscriptions"
Jun 28, 2022 09:52:11.615 [0x7f36da967b38] Debug — Subscription: Scheduling subscriptions.
Jun 28, 2022 09:52:11.617 [0x7f36da967b38] Debug — Subscription: Initialized 0 schedulers.
Jun 28, 2022 09:52:11.617 [0x7f36da967b38] Debug — Subscription: Starting with 0 grabs, scheduled 0 active ones preemptively.
Jun 28, 2022 09:52:11.617 [0x7f36da967b38] Debug — Subscription: Scheduled all subscriptions in 1 ms.
Jun 28, 2022 09:52:11.617 [0x7f36da967b38] Debug — Activity: Ended activity 7ff6fa2c-2bc8-4393-bd3e-1b533ed71e45.
Jun 28, 2022 09:52:11.617 [0x7f36da967b38] Debug — Subscription: There are 0 active grabs at the end.
Jun 28, 2022 09:52:11.618 [0x7f36da967b38] Debug — Activity: Ended activity 22c2557f-445d-40ae-bed8-7cf9c26d6c4d.
Jun 28, 2022 09:52:11.618 [0x7f36da967b38] Debug — Subscription: Refreshed all content in 7 ms.
Jun 28, 2022 09:52:11.636 [0x7f36dabf1b38] Debug — Request: [192.168.0.2:51809 (Allowed Network (WAN))] GET /library/sections (11 live) TLS GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:11.637 [0x7f36db4b6b38] Debug — Completed: [192.168.0.2:51809] 200 GET /library/sections (11 live) TLS GZIP 1ms 804 bytes (pipelined: 32)
Jun 28, 2022 09:52:11.672 [0x7f36dabf1b38] Debug — Request: [192.168.0.2:51809 (Allowed Network (WAN))] GET /library/sections (11 live) TLS GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:11.673 [0x7f36db4b6b38] Debug — Completed: [192.168.0.2:51809] 200 GET /library/sections (11 live) TLS GZIP 0ms 804 bytes (pipelined: 33)
Jun 28, 2022 09:52:11.686 [0x7f36dabf1b38] Debug — Request: [192.168.0.2:51809 (Allowed Network (WAN))] GET /media/providers (11 live) TLS GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:11.688 [0x7f36db4b6b38] Debug — Completed: [192.168.0.2:51809] 200 GET /media/providers (11 live) TLS GZIP 1ms 4650 bytes (pipelined: 34)
Jun 28, 2022 09:52:11.713 [0x7f36db4d9b38] Debug — Using X-Forwarded-For: 2.216.126.13 as remote address
Jun 28, 2022 09:52:11.713 [0x7f36dabf1b38] Debug — Request: [192.168.90.254:56350 (WAN)] GET /media/providers (11 live) GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:11.714 [0x7f36db4b6b38] Debug — Completed: [192.168.90.254:56350] 200 GET /media/providers (11 live) GZIP 1ms 4650 bytes (pipelined: 4)
Jun 28, 2022 09:52:11.727 [0x7f36dabf1b38] Debug — Request: [192.168.0.2:51809 (Allowed Network (WAN))] GET /media/providers (11 live) TLS GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:11.728 [0x7f36db4b6b38] Debug — Completed: [192.168.0.2:51809] 200 GET /media/providers (11 live) TLS GZIP 1ms 4650 bytes (pipelined: 35)
Jun 28, 2022 09:52:11.748 [0x7f36db4d9b38] Debug — Using X-Forwarded-For: 2.216.126.13 as remote address
Jun 28, 2022 09:52:11.748 [0x7f36dabf1b38] Debug — Request: [192.168.90.254:56350 (WAN)] GET /media/providers (11 live) GZIP Signed-in Token (xxxxxxxxxx) (Safari)
Jun 28, 2022 09:52:11.749 [0x7f36db4d9b38] Debug — Completed: [192.168.90.254:56350] 200 GET /media/providers (11 live) GZIP 1ms 4650 bytes (pipelined: 5)
6

Could you provide the full server logs zip file, and if possible a sample of one of the tracks from the album you’re having issues with.

7

I just created a fresh Music Library. Lots of content is not added. When it does add an artist, it only seems to add a single track to an album. Full logs and example track here;

Plex.zip (13.7 MB)

Thanks for taking a look into this.

8

@drzoidberg33 Sorry to bother you but any chance you managed to have a look at this yet? Thanks

9

@drzoidberg33 Just checking in to see if you’ve managed to take a look at this. Thanks again.

10

@drzoidberg33 Checking in again to see if you’ve had chance to look into this?

To add some further info. If I change the library to use the legacy Plex Music Scanner, all my music is successfully added to my library. I can then switch back to the new Plex Music scanner and my music remains but new music added after this is not found and the logs show the same error.

Here’s a Reddit post by someone with the same issue. Thanks;

11

FYI… Switching from the new modern plex scanner/agent to the old legacy one is strongly discouraged as it can break library functions. There has been a few threads regarding it.

As a test, if you create a new library using the modern plex scanner/agent is the content found as you would expect?

12

Thanks,

Yes, I’ve created a new library with the modern Plex Music scanner. The result is that for any Artist that Plex adds, it adds an arbitrary number of their Albums/Singles & EPs, usually just 1, and each added album only has a limited number of tracks added, usually just a single track.

I cannot identify a pattern to what artists/albums/tracks Plex adds. Here’s the stats from the 2 scanners;

Plex Music Scanner (legacy)
Arists = 461
Albums = 3189
Tracks = 39835

Plex Music (new)
Arists = 133
Albums = 208
Tracks = 209

My library has good metadata and follows the Plex naming conventions. The legacy and modern music scanners used to work fine and my TV/Movie libraries continue to work correctly.

  • I have tried a clean PMS install.
  • I have tried the beta branch.
  • I have tried moving my music to a new hard drive.
  • I have reapplied permissions.
  • I have checked my files are owned by the UID and PID mapped to the Plex container.
13

Interesting, could you give me a screenshot or directory listing of the media files on disk? Also a screenshot or ffmpeg output of the metadata from one file would also be useful.

Edit: wow, that’s some delta difference. Must be naming or metadata so a example might help identify. Maybe the scanner is having trouble parsing some tag in your files.

I also assume you have updated to the current plex server version? The version in the OP is old now and later versions has fixes to the music scanner.

14

list.txt (3.2 MB)
output_file.txt (3.8 KB)
01 - Leave Home.mp3.zip (12.7 MB)

Thanks for the help! Attached is;

  • Directory listing for my Music folder.
  • Example music file, /The Chemical Brothers/Exit Planet Dust/01 - Leave Home.mp3 which the new scanner does not import but the old scanner does
  • FFMPEG output for the above file

My PMS version is 1.28.1.6018

15

I see this in your log file:

Jun 28, 2022 00:09:30.753 [0x7f36df481b60] WARN - Failed to create temp dir "/tmp/pms-9e96527e-0261-46e3-9162-735b9aae0479": 13, Permission denied

Without a working tmp directory a lot of things will not work correctly, including scanning music. You should start there and see why this temp path is not accessible.

1 Like
16

Thank you!!!

I chowned that folder to the UID and PID mapped to the Plex container and now the new Plex Music scanner works.

It’s odd that Movies, Shows, DVR and the legacy Music scanner etc all work fine without this folder and it only seems to manifest an issue with the new Music scanner. Anyway, thank you again, this has had me stumped for weeks and weeks and I really appreciate all the help I’ve received!

17

No problem,

Certain operations require writing files to the temp folder and some don’t, but it’s critical that this path is accessible otherwise you will find strange things happening (as you found out :sweat_smile: )

18

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