Movies passing the rules not being added to the Collection

[mlamoure]

Describe the bug
Been using Maintainerr for some time, with no changes to my rules. Recently a number of movies have been removed from my Collection, but are still passing the rule when evaluated.

Other than TMDB items not being found, I only see this error in my logs:
[maintainerr] | 02/05/2024 14:07:03 [INFO] [RuleComparatorService] Something went wrong while running rule Movies Leaving Plex Soon
[maintainerr] | 02/05/2024 14:07:03 [ERROR] [ExceptionsHandler] Cannot read properties of undefined (reading 'stats')

I do not use the exclusions feature, so it's not that.

One potential culprit is that my Plex has been slow to respond to metadata queries at times. I'm not sure how resilient maintainerr is to retry if a query fails? I have a heafty Plex server but it has a large library. I've been running some cleaning scripts to clean up the bundles, etc.

Screenshots

Device (please complete the following information):

• OS: Docker on Ubuntu 22.04
• Version 2.0.3

[jorenn92]

Hey! It seems that the rule encountered an undefined statistics object, which is unexpected considering the object is initialized at the start. While it's possible that this issue could stem from a sluggish Plex server response, the error isn't what i'd expect in such scenarios.

API calls to Plex are configured with a timeout value of 5 seconds. If this limit is exceeded, the returned item is likely to be null. Although some calls are retried, not all Plex calls benefit from this mechanism. Maintainerr relies on an external library for Plex API communication, which currently lacks a built-in retry feature.

Is this the first time you encountered this issue? Does the problem resolve itself upon next rule executions?

[mlamoure]

Hi--

I've had the issue since 5/1/24 when you see from the screenshot that items were mysteriously removed but are still resolving as true when evaluated individually. The error I posted only occurs once. I have not been able to reproduce that error since the one occurrence.

To test, I restarted the Maintainerr container and manually ran the Movies Rules. I only see this in my logs, it's been 5 hours since I ran the rules manually:

[maintainerr] | 03/05/2024 16:34:54 [INFO] [NestApplication] Nest application successfully started [maintainerr] | 03/05/2024 16:35:11 [INFO] [RuleExecutorService] Starting Execution of all active rules [maintainerr] | 03/05/2024 16:35:11 [INFO] [RuleExecutorService] Executing rules for 'Movies Leaving Plex Soon' [maintainerr] | 03/05/2024 19:27:12 [WARN] [RadarrGetterService] [TMDb] Failed to fetch TMDb id for 'Bon Jovi Unplugged on VH1'

Is there any way I can increase the logging to see what's happening?

[mlamoure]

After another day, the movies returned to the Collection. The countdown dates are reset, but they are back. I'm fine with closing this, or I can provide some logs to help track down if there is a bug. Thanks again.

[jorenn92]

The only method to enhance logging is by enabling the 'DEBUG' flag in your Docker Compose/run command. However, I'm uncertain if this will provide additional information in this scenario.

If you encounter this issue again, it would be great if you were able to obtain some debug logs from Maintainerr and Plex's side. But it may not be straightforward to gather them when the problem doesn't happen consistently.

I'll leave this issue open for a few weeks. Please keep me informed if it reoccurs. Otherwise, I'll close it later.

Thank you for reporting this!

[mlamoure]

Hi there--

Sadly, the issue has reoccurred twice.

As you can see from the screenshot, all of the movies in my collection were removed. However, the movies that were removed were not processed (they had several days remaining), but are still passing the rule.

Here is my rules, it's fairly straightforward:

mediaType: MOVIES
rules:
  - "0":
      - firstValue: Plex.viewCount
        action: EQUALS
        customValue:
          type: number
          value: 0
      - operator: OR
        firstValue: Plex.lastViewedAt
        action: BEFORE
        customValue:
          type: custom_days
          value: "180"
  - "1":
      - operator: AND
        firstValue: Radarr.tags
        action: NOT_CONTAINS_PARTIAL
        customValue:
          type: text
          value: never_expire
  - "2":
      - operator: AND
        firstValue: Plex.addDate
        action: BEFORE
        customValue:
          type: custom_days
          value: "335"

Another odd thing -- My rules are set to process at 6am. Collections are set to 7am. Unless the timezone is off, it shouldn't be running at 3pm like the Logs say. I'm passing my timezone in through my docker-config like so:

   environment:
      - "PUID=${PUID}"
      - "PGID=${PGID}"
      - "TZ=${TZ}"
 

.env file:

TZ=America/New_York

[jorenn92]

Hey

Hi there--

Sadly, the issue has reoccurred twice.

As you can see from the screenshot, all of the movies in my collection were removed. However, the movies that were removed were not processed (they had several days remaining), but are still passing the rule.

Here is my rules, it's fairly straightforward:

mediaType: MOVIES
rules:
  - "0":
      - firstValue: Plex.viewCount
        action: EQUALS
        customValue:
          type: number
          value: 0
      - operator: OR
        firstValue: Plex.lastViewedAt
        action: BEFORE
        customValue:
          type: custom_days
          value: "180"
  - "1":
      - operator: AND
        firstValue: Radarr.tags
        action: NOT_CONTAINS_PARTIAL
        customValue:
          type: text
          value: never_expire
  - "2":
      - operator: AND
        firstValue: Plex.addDate
        action: BEFORE
        customValue:
          type: custom_days
          value: "335"

Another odd thing -- My rules are set to process at 6am. Collections are set to 7am. Unless the timezone is off, it shouldn't be running at 3pm like the Logs say. I'm passing my timezone in through my docker-config like so:

   environment:
      - "PUID=${PUID}"
      - "PGID=${PGID}"
      - "TZ=${TZ}"
 

.env file:

TZ=America/New_York

Did you manage to catch Plex logs when this failed? I'm still leaning towards network issues.

As for the timestamp, what time does it log the executions in the container log? Perhaps the UI is misinterpreting the timestamp fetched from the database.

[mlamoure]

Hi there-

I witnessed live when the error occurred, but I'm not having much luck diagnosing it.

• Plex is actually crashing, but very momentarily. I downloaded the logs, but do not see much happening at the time of the crash. This is what I see, many times over:

May 27, 2024 14:41:33.505 [134737763642168] DEBUG - [Req#7c9f6a] Setting container serialization range to [0, 0] (total=-1) May 27, 2024 14:41:33.526 [134737763642168] DEBUG - [Req#7c9f6a] PlayQueue: Converted 'server://8fa4ff9f71a29e0802901c71a3207281050cdceb/com.plexapp.plugins.library/library/sections/1/all?type=1&sort=originallyAvailableAt%3Adesc&push=1&genre=78&pop=1' to 'library://x/directory/%2Flibrary%2Fsections%2F1%2Fall%3Ftype%3D1%26sort%3DoriginallyAvailableAt%253Adesc%26push%3D1%26genre%3D78%26pop%3D1'

• All of a sudden, it ends without an error or critical item in the log. Plex restarts rather quickly, I can see this in the log files. At this point the Maintainerr logs show all movies being removed that had been previously added to the collection, even though those items are still passing the rules:

[maintainerr] | 27/05/2024 14:46:19 [INFO] [CollectionsService] Removing media with id 4027 from collection..

• It appears that the container timezone is correct. And I see the rules and collection jobs start in the docker log at the time I've set up in my config. However, I'm unable to explain why I'm seeing Maintainerr run at 2pm when my rules and collections jobs are set to 6am and 7am respectively. Unless they are still running after 6 hours? Could that be?

[jorenn92]

Hi there-

I witnessed live when the error occurred, but I'm not having much luck diagnosing it.

* Plex is actually crashing, but very momentarily.  I downloaded the logs, but do not see much happening at the time of the crash.  This is what I see, many times over:

May 27, 2024 14:41:33.505 [134737763642168] DEBUG - [Req#7c9f6a] Setting container serialization range to [0, 0] (total=-1) May 27, 2024 14:41:33.526 [134737763642168] DEBUG - [Req#7c9f6a] PlayQueue: Converted 'server://8fa4ff9f71a29e0802901c71a3207281050cdceb/com.plexapp.plugins.library/library/sections/1/all?type=1&sort=originallyAvailableAt%3Adesc&push=1&genre=78&pop=1' to 'library://x/directory/%2Flibrary%2Fsections%2F1%2Fall%3Ftype%3D1%26sort%3DoriginallyAvailableAt%253Adesc%26push%3D1%26genre%3D78%26pop%3D1'

* All of a sudden, it ends without an error or critical item in the log.  Plex restarts rather quickly, I can see this in the log files.  At this point the Maintainerr logs show all movies being removed that had been previously added to the collection, even though those items are still passing the rules:

[maintainerr] | 27/05/2024 14:46:19 [INFO] [CollectionsService] Removing media with id 4027 from collection..

* It appears that the container timezone is correct.  And I see the rules and collection jobs start in the docker log at the time I've set up in my config.  However, I'm unable to explain why I'm seeing Maintainerr run at 2pm when my rules and collections jobs are set to 6am and 7am respectively.  Unless they are still running after 6 hours?  Could that be?

If Plex crashes, some API calls may return empty responses. This could explain why Maintainerr detects discrepancies in some rule data. Do you think Maintainerr is overwhelming Plex? Maintainerr has built-in rate limiting & caching, so it shouldn't overload Plex. However, it might still be too aggressive.

Are you running Maintainerr against a large library? If your library is substantial, rule handling could take several hours due to the rate limiting.