Plex Movie agent only grabbing basic information

Plex Media Server Metadata & Adding Files
, ,
41

@drzoidberg33, I installed your custom package, here’s the log output:

Jun 30, 2021 19:40:37.334 [0x7f0de1d1ab38] Débogage — Activity: registered new activity 1a8937c7-a4df-4db0-83d4-cd8ba667851c - "Updating Metadata"
Jun 30, 2021 19:40:37.334 [0x7f0de1d1ab38] Débogage — Activity: updated activity 1a8937c7-a4df-4db0-83d4-cd8ba667851c - completed 49.0% - Updating Metadata
Jun 30, 2021 19:40:37.335 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] Connection 100 seems to be dead!

Jun 30, 2021 19:40:37.335 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] Closing connection 100

Jun 30, 2021 19:40:37.335 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] TLSv1.2 (OUT), TLS alert, close notify (256):

Jun 30, 2021 19:40:37.337 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] Found bundle for host metadata.provider.plex.tv: 0x7f0de23e1790 [can multiplex]

Jun 30, 2021 19:40:37.344 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl]   Trying 104.18.12.47:443...

Jun 30, 2021 19:40:37.348 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] Connected to metadata.provider.plex.tv (104.18.12.47) port 443 (#102)

Jun 30, 2021 19:40:37.348 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] ALPN, offering h2

Jun 30, 2021 19:40:37.348 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] ALPN, offering http/1.1

Jun 30, 2021 19:40:37.361 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] successfully set certificate verify locations:

Jun 30, 2021 19:40:37.361 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl]  CAfile: /volume1/.@plugins/AppCentral/plexmediaserver/Resources/cacert.pem

Jun 30, 2021 19:40:37.361 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl]  CApath: /etc/ssl/certs

Jun 30, 2021 19:40:37.361 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] SSL re-using session ID

Jun 30, 2021 19:40:37.361 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] TLSv1.3 (OUT), TLS handshake, Client hello (1):

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] TLSv1.3 (IN), TLS handshake, Server hello (2):

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] TLSv1.2 (IN), TLS handshake, Finished (20):

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] TLSv1.2 (OUT), TLS handshake, Finished (20):

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] SSL connection using TLSv1.2 / ECDHE-ECDSA-CHACHA20-POLY1305

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] ALPN, server accepted to use h2

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] Server certificate:

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl]  subject: C=US; ST=California; L=San Francisco; O=Cloudflare, Inc.; CN=plex.tv

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl]  start date: May 20 00:00:00 2021 GMT

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl]  expire date: Aug 17 23:59:59 2021 GMT

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl]  subjectAltName: host "metadata.provider.plex.tv" matched cert's "*.provider.plex.tv"

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl]  issuer: C=US; O=Cloudflare, Inc.; CN=Cloudflare Inc ECC CA-3

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl]  SSL certificate verify ok.

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] Using HTTP2, server supports multi-use

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] Connection state changed (HTTP/2 confirmed)

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0

Jun 30, 2021 19:40:37.370 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] Using Stream ID: 1 (easy handle 0x7f0de238a9e0)

Jun 30, 2021 19:40:37.375 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] Connection state changed (MAX_CONCURRENT_STREAMS == 256)!

Jun 30, 2021 19:40:37.375 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] HTTP/2 stream 0 was not closed cleanly: PROTOCOL_ERROR (err 1)

Jun 30, 2021 19:40:37.375 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] stopped the pause stream!

Jun 30, 2021 19:40:37.376 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] Connection #102 to host metadata.provider.plex.tv left intact

Jun 30, 2021 19:40:37.376 [0x7f0de1d1ab38] Erreur — [MetadataAgent/tv.plex.agents.movie] Error issuing curl_easy_perform(handle): 92
Jun 30, 2021 19:40:37.376 [0x7f0de1d1ab38] Erreur — [MetadataAgent/tv.plex.agents.movie] HTTP -92 downloading url https://metadata.provider.plex.tv/library/metadata/5d77704631d95e001f19d8a0?includeReviews=1&X-Plex-Country=FR&X-Plex-Language=en-US&X-Plex-Text-Format=markdown&X-Plex-Api-Token=xxxxxxxxxxxxxxxxxxxx
Jun 30, 2021 19:40:37.376 [0x7f0de1d1ab38] Erreur — [MetadataAgent/tv.plex.agents.movie] Request for item plex://movie/5d77704631d95e001f19d8a0 has failed
Jun 30, 2021 19:40:37.377 [0x7f0de1d1ab38] Débogage — [JobRunner] Job running: FFMPEG_EXTERNAL_LIBS='/volume1/Plex/Library/Plex\ Media\ Server/Codecs/fa235d6-3858-linux-x86_64/' X_PLEX_TOKEN='xxxxxxxxxxxxxxxxxxxx' '/volume1/.@plugins/AppCentral/plexmediaserver/Plex Media Scanner' '--match' '--type' '1' '--log-file-suffix' ' Matcher' '--item' '27125'
Jun 30, 2021 19:40:37.378 [0x7f0de1d1ab38] Débogage — [JobRunner] Jobs: Starting child process with pid 6631
Jun 30, 2021 19:40:37.823 [0x7f0de1d1ab38] Débogage — Loading information from media bundle for part ID 46536 from "/volume1/Plex/Library/Plex Media Server/Media/localhost/2/987baf7723dec222e80aba5f3d344cb48fe61c1.bundle/Contents/Plex Movie"
Jun 30, 2021 19:40:37.823 [0x7f0de1d1ab38] Débogage — Loaded metadata for Sans un bruit 2 (ID 27125) in 27ms
Jun 30, 2021 19:40:37.824 [0x7f0de1d1ab38] Débogage — Done with metadata update for 27125
Jun 30, 2021 19:40:37.824 [0x7f0de1d1ab38] Débogage — Activity: Ended activity 1a8937c7-a4df-4db0-83d4-cd8ba667851c.

From what I can tell, the culprit is around there :

Jun 30, 2021 19:40:37.375 [0x7f0de1d1ab38] Débogage — [MetadataAgent/tv.plex.agents.movie] [libcurl] Connection state changed (MAX_CONCURRENT_STREAMS == 256)!
42

If I may, my guess is that your problem is related to MTU being too low or too high.

43

MTU is standard at 1500

44

MAX_CONCURRENT_STREAMS == 256 isn’t an error, it’s a normal part of HTTP/2 connections.

But the next message with was not closed cleanly is sure an issue!

The error here happens so fast. MTU issues often manifest as slowness-before-breakage.

My totally uninformed guess is the client or server are saying something that HTTP/2 - which is super picky - doesn’t like.

Curious what @drzoidberg33 says.

/watching

45

From what I found around the web, it’s likely a server side error.

See here for example : 7.62.0 giving "HTTP/2 stream 0 was not closed cleanly" error (7.61.1 was ok) · Issue #3206 · curl/curl · GitHub

An easy fix would be to force the request over HTTP/1.1 instead of HTTP/2

46

Maybe adding verbose logging to what happens inside libnghttp2 (used by curl for all things related to HTTP/2) could get us more details of what breaks exactly

1 Like
47

Or maybe check that the headers are compliant with HTTP/2

example: curl: (92) HTTP/2 stream 0 was not closed cleanly: PROTOCOL_ERROR (err 1) | OpenLiteSpeed Community and News

48

… but what’s different for your system, vs. others? Plex is the same.

Pull one of the LACP links, just in case there’s some issue with packet ordering? (even less likely than MTU, lol!)

49

1- Why would this one request fail, when everything else runs just fine on the NAS ? What’s different for Plex Server vs others ?
2- I already thought of that and tried, same error.

This is an HTTP/2 protocol error. We just have to find the source of this error :wink:

Edit: Furthermore, when using LACP, it always uses the same link to talk to a destination.

50

I see that you guys troubleshooting application, but have you tried disabling lacp?

51

See above

52

I agree!

More shameless grasping at straws: does the NAS (or your router?) have any fancy security/IDS/network defense features, anything like that?

If my dumb ideas don’t help, then I guess I’m no help at all. :slight_smile:

A very good point.

Except for broken implementations, which are disturbingly common. But you’ve ruled that out.

Dumb idea 12: does a test Library with the old agent work?

53

Those aren’t dumb ideas :wink:

Haven’t tried using the legacy agent. I’d expect it doesn’t use Plex’s metadata server, so would work as expected ?

But I expect Plex will drop support for that legacy agent in the future, what happens then if this bug is still present ?

No IDS present there. Only basic firewalling, and the necessary ports are open.

54

I’m not sure! I think it also interacts with the Plex servers too, but the legacy agent is hosted in Python. I’m just guessing it wouldn’t exercise the same connectivity libraries.

I’ll bet $1 it works, and that it doesn’t actually give any new information. :slight_smile:

You don’t want to use the legacy agent long term. The new one is also a billion times faster.

55

Hello @drzoidberg33 ,

Anything new on your side ?

56

@drzoidberg33
curl was updated in the latest Asustor ADM beta, so I reran the first test:

Freeben@FreeNAS2:/volume1/home/Freeben $ curl -v -4 --http2 https://metadata.provider.plex.tv
*   Trying 104.18.13.47:443...
* Connected to metadata.provider.plex.tv (104.18.13.47) port 443 (#0)
* ALPN, offering http/1.1
* successfully set certificate verify locations:
*  CAfile: none
*  CApath: /etc/ssl/certs/
* TLSv1.3 (OUT), TLS handshake, Client hello (1):
* TLSv1.3 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Change cipher spec (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-ECDSA-CHACHA20-POLY1305
* ALPN, server accepted to use http/1.1
* Server certificate:
*  subject: C=US; ST=California; L=San Francisco; O=Cloudflare, Inc.; CN=plex.tv
*  start date: May 20 00:00:00 2021 GMT
*  expire date: Aug 17 23:59:59 2021 GMT
*  subjectAltName: host "metadata.provider.plex.tv" matched cert's "*.provider.plex.tv"
*  issuer: C=US; O=Cloudflare, Inc.; CN=Cloudflare Inc ECC CA-3
*  SSL certificate verify ok.
> GET / HTTP/1.1
> Host: metadata.provider.plex.tv
> User-Agent: curl/7.77.0
> Accept: */*
>
* Mark bundle as not supporting multiuse
< HTTP/1.1 200 OK
< Date: Thu, 08 Jul 2021 10:32:09 GMT
< Content-Type: application/xml; charset=utf-8
< Content-Length: 834
< Connection: keep-alive
< Access-Control-Allow-Origin: *
< Cache-Control: max-age=86400
< Content-Language: en
< Etag: W/"342-WP9vNDmXmQLaI85a5B/4NEhEXlo"
< Expect-Ct: max-age=0
< Referrer-Policy: no-referrer
< Strict-Transport-Security: max-age=31536000; includeSubDomains; preload
< Vary: Accept, Accept-Encoding, X-Plex-Language, X-Plex-Provider-Version
< X-Content-Type-Options: nosniff
< X-Dns-Prefetch-Control: off
< X-Download-Options: noopen
< X-Frame-Options: SAMEORIGIN
< X-Permitted-Cross-Domain-Policies: none
< X-Plex-Timestamp: 1624591460
< X-Plex-Version: 0e8d2b4
< X-Xss-Protection: 0
< CF-Cache-Status: HIT
< Age: 1224
< Accept-Ranges: bytes
< Server: cloudflare
< CF-RAY: 66b8a5a0ad2cee13-CDG
<
* Connection #0 to host metadata.provider.plex.tv left intact
<?xml version="1.0"?><MediaProvider icon="https://provider-static.plex.tv/icons/metadata-560.svg" identifier="tv.plex.provider.metadata" protocols="stream" version="1.3.0" title="Metadata"><Feature type="metadata" key="/library/metadata"/><Feature type="actions"><Action id="addToWatchlist" key="/actions/addToWatchlist" reverseKey="/actions/removeFromWatchlist"/></Feature><Feature type="availability" key="/availability"/><Feature type="availability-platforms" key="/availability-platforms"/><Feature type="location" key="/location"/><Feature type="universalsearch" key="/library/search"/><Feature public="1" type="imagetranscoder" key="https://images.plex.tv/photo"/><Feature flavor="universal" type="playqueue" key="https://play.provider.plex.tv/playQueues"/><Feature type="match" key="/library/metadata/matches"/></MediaProvider>

Seems like the web server on Plex’s end only offers HTTP/1.1 now. But the problem remains the same :disappointed_relieved:

57

Hey sorry, I haven’t been on the forums much the last few days.

Unfortunately that additional logging doesn’t seem to really add much more useful information. I’ve asked the team about this and the only thing that may be useful is getting a packet capture (pcap) and seeing what’s happening in there during one of these requests.

If you could get a capture during one of the refreshes and pass on the file then that may help track down the culprit.

58

No, it still supports HTTP/2. Not sure why it’s falling back there.

59

Curl doesn’t seem to have offered h2. Was it built with nghttp2?

60

I’ll see what I can do about the pcap. The NAS OS probably won’t be able to do this, given how limited it is, but I might be able to mirror the network port on the router and do the pcap from another computer. I’ll take a look at it when I’m home (at work right now).