search

arabcoders / watchstate

Self-hosted service to sync your plex, jellyfin and emby play state. without relying on 3rd-party external services.
MIT License
452 stars 9 forks source link

[BUG] Error Log missing entries #471

Closed jiggyjigsj closed 3 months ago

jiggyjigsj commented 4 months ago

Describe the bug I am getting a few errors while trying to import, but the error log seems to be empty. Shouldn't {{reason}} be filled with the error?

[2024-05-30T17:02:02+00:00] NOTICE: MAPPER: [DEST-SERVER] item [ITEM to SYNC] is marked as [unplayed] vs local state [played], However due to the following reason ({reason}) it was not considered as valid state.

To Reproduce Running state:import -vvv from the console.

Expected behavior Expect the output to show the error instead of {{reason}}.

Screenshots

image

Basic report

$ docker exec -ti watchstate console system:report
[ Basic Report ]

WatchState Version: 20240527-01b7fb5
PHP Version: 8.3.7
Timezone: UTC
Running in Container? Yes
Data Path: /config
Temp Path: /config
Database Migrated?: Yes
Has .env file? Yes
Is Tasks Runner working? Yes
Report Generated At: 2024-05-30T17:06:58+00:00
[ Backends ]

[ Jellyfin (10.9.3) ==> Jellyfin ]

Is backend URL HTTPS? Yes
Has Unique Identifier? Yes
Has User? Yes
Export Enabled? Yes
Time since last export? 1970-01-01T00:00:00+00:00
Play state import enabled? Yes
Metadata only import enabled? No
Time since last import? 2024-05-30T17:05:10+00:00
Has webhook token? Yes
Is webhook match user id enabled? No
Is webhook match backend unique id enabled? No
Has custom options? No
{}

[ Plex (1.40.2.8395-c67dce28e) ==> Nas ]

Is backend URL HTTPS? No
Has Unique Identifier? Yes
Has User? Yes
Export Enabled? Yes
Time since last export? 2024-05-30T16:30:54+00:00
Play state import enabled? Yes
Metadata only import enabled? Yes
Time since last import? 2024-05-30T17:05:11+00:00
Has webhook token? Yes
Is webhook match user id enabled? No
Is webhook match backend unique id enabled? No
Has custom options? Yes
{"IMPORT_METADATA_ONLY":true,"ADMIN_TOKEN":"**HIDDEN**"}

[ Tasks ]

[ Import ]

Is Task enabled? Yes
Which flags are used to run the task? -v
When the task scheduled to run at? 0 */1 * * *
When is the next scheduled run? 2024-05-30T18:00:00+00:00

[ Export ]

Is Task enabled? Yes
Which flags are used to run the task? -v
When the task scheduled to run at? 30 */1 * * *
When is the next scheduled run? 2024-05-30T17:30:00+00:00

[ Push ]

Is Task enabled? Yes
Which flags are used to run the task? -v
When the task scheduled to run at? */10 * * * *
When is the next scheduled run? 2024-05-30T17:10:00+00:00

[ Progress ]

Is Task enabled? Yes
Which flags are used to run the task? -v
When the task scheduled to run at? */45 * * * *
When is the next scheduled run? 2024-05-30T17:45:00+00:00

[ Backup ]

Is Task enabled? Yes
Which flags are used to run the task? -v
When the task scheduled to run at? 0 6 */3 * *
When is the next scheduled run? 2024-05-31T06:00:00+00:00

[ Prune ]

Is Task enabled? Yes
Which flags are used to run the task? -v
When the task scheduled to run at? 0 */12 * * *
When is the next scheduled run? 2024-05-31T00:00:00+00:00

[ Indexes ]

Is Task enabled? Yes
Which flags are used to run the task? -v
When the task scheduled to run at? 0 3 * * 3
When is the next scheduled run? 2024-06-05T03:00:00+00:00

[ Requests ]

Is Task enabled? Yes
Which flags are used to run the task? -v --no-stats
When the task scheduled to run at? */2 * * * *
When is the next scheduled run? 2024-05-30T17:08:00+00:00

[ Logs ]

[ /config/logs/app.20240530.log ]

[2024-05-30T13:01:07.368519+00:00] logger.ERROR: Request for [Jellyfin] [One Timer - Curated] items count returned with unexpected [500] status code. {"library":{"id":"57ed97052f9b7dd679f5f8771a39178d","type":"movies","url":"https://jellyfin-server/Users/USER_ID/items/?sortBy=DateCreated&sortOrder=Ascending&parentId=57ed97052f9b7dd679f5f8771a39178d&recursive=true&excludeLocationTypes=Virtual&includeItemTypes=Movie%2CEpisode&startIndex=0&limit=0"}} []
[2024-05-30T13:01:07.526368+00:00] logger.ERROR: Request for [Jellyfin] [Binge Watch] items count returned with unexpected [500] status code. {"library":{"id":"4cc38d09598ed6f604889ad3afda68f6","type":"tvshows","url":"https://jellyfin-server/Users/USER_ID/items/?sortBy=DateCreated&sortOrder=Ascending&parentId=4cc38d09598ed6f604889ad3afda68f6&recursive=true&excludeLocationTypes=Virtual&includeItemTypes=Movie%2CEpisode&startIndex=0&limit=0"}} []

[ /config/logs/access.20240530.log ]

[2024-05-30T17:01:47.415738+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/system/env HTTP/1.1" 200 5223 "http://WATCHSTATE_NAME:8989/env" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-30T17:01:49.695939+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/tasks HTTP/1.1" 200 1919 "http://WATCHSTATE_NAME:8989/tasks" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-30T17:01:58.211047+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/tasks/import HTTP/1.1" 200 231 "http://WATCHSTATE_NAME:8989/console" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-30T17:01:58.226885+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/system/command/ HTTP/1.1" 200 0 "http://WATCHSTATE_NAME:8989/console" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-30T17:03:23.093139+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/history HTTP/1.1" 200 3281 "http://WATCHSTATE_NAME:8989/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-30T17:03:23.108022+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/system/version HTTP/1.1" 200 30 "http://WATCHSTATE_NAME:8989/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-30T17:03:23.133432+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/logs/recent HTTP/1.1" 200 20180 "http://WATCHSTATE_NAME:8989/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-30T17:04:38.788290+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/system/command/ HTTP/1.1" 200 0 "http://WATCHSTATE_NAME:8989/console" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-30T17:04:56.064137+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/system/command/ HTTP/1.1" 200 0 "http://WATCHSTATE_NAME:8989/console" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-30T17:05:09.428096+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/system/command/ HTTP/1.1" 200 0 "http://WATCHSTATE_NAME:8989/console" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []

[ /config/logs/task.20240530.log ]

[2024-05-30T17:01:03+00:00] NOTICE: SYSTEM: Finished waiting on [9] requests.
[2024-05-30T17:01:03+00:00] NOTICE: SYSTEM: Found [14] updated objects.
┌─────────┬───────┬─────────┬────────┐
│ Type    │ Added │ Updated │ Failed │
├─────────┼───────┼─────────┼────────┤
│ Movie   │ 0     │ 0       │ 0      │
├─────────┼───────┼─────────┼────────┤
│ Episode │ 0     │ 14      │ 0      │
└─────────┴───────┴─────────┴────────┘

[ /config/logs/webhook.20240530.log ]

webhook log file is empty or does not exists.

[ /config/logs/app.20240529.log ]

app log file is empty or does not exists.

[ /config/logs/access.20240529.log ]

[2024-05-29T02:07:10.823989+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/history/ HTTP/1.1" 200 17469 "http://WATCHSTATE_NAME:8989/history" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-29T02:07:56.172837+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/history HTTP/1.1" 200 3210 "http://WATCHSTATE_NAME:8989/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-29T02:07:56.183765+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/logs/recent HTTP/1.1" 200 10993 "http://WATCHSTATE_NAME:8989/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-29T02:07:59.455757+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/tasks HTTP/1.1" 200 1919 "http://WATCHSTATE_NAME:8989/tasks" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-29T02:08:01.260581+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/logs HTTP/1.1" 200 592 "http://WATCHSTATE_NAME:8989/logs" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-29T20:15:39.066567+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/system/version HTTP/1.1" 200 30 "http://WATCHSTATE_NAME:8989/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-29T20:15:39.069184+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/history HTTP/1.1" 200 3210 "http://WATCHSTATE_NAME:8989/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-29T20:15:39.094477+00:00] http.INFO: BRWOSER_IP - "GET /v1/api/logs/recent HTTP/1.1" 200 12571 "http://WATCHSTATE_NAME:8989/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-29T21:15:39.539060+00:00] http.INFO: BRWOSER_IP - "GET /assets/builds/latest.json HTTP/1.1" 200 71 "http://WATCHSTATE_NAME:8989/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []
[2024-05-29T22:15:40.322226+00:00] http.INFO: BRWOSER_IP - "GET /assets/builds/latest.json HTTP/1.1" 200 71 "http://WATCHSTATE_NAME:8989/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/123.0.0.0 Safari/537.36" "-" [] []

[ /config/logs/task.20240529.log ]

[2024-05-29T23:30:15+00:00] NOTICE: SYSTEM: Using push mode for [0] backends and export mode for [1] backends.
[2024-05-29T23:30:15+00:00] NOTICE: Export mode start.
[2024-05-29T23:30:15+00:00] NOTICE: SYSTEM: Preloading DirectMapper data.
[2024-05-29T23:30:15+00:00] NOTICE: SYSTEM: Preloading DirectMapper data is complete.
[2024-05-29T23:30:15+00:00] NOTICE: SYSTEM: Exporting play state changes since [2024-05-29 22:30:02 UTC] to [Nas].
[2024-05-29T23:30:16+00:00] NOTICE: SYSTEM: Sending [2] play state comparison requests.
[2024-05-29T23:30:17+00:00] NOTICE: SYSTEM: Sent [2] play state comparison requests.
[2024-05-29T23:30:17+00:00] NOTICE: Export mode ends.
[2024-05-29T23:30:17+00:00] NOTICE: SYSTEM: No play state changes detected.

[ /config/logs/webhook.20240529.log ]

webhook log file is empty or does not exists.

Additional context

arabcoders commented 4 months ago

You are correct it's probably due to us shuffling the code block recently.

However in response to your issue it's probably related to this

https://github.com/arabcoders/watchstate/blob/master/FAQ.md#i-keep-receiving-jellyfin-item-id-name-is-marked-as-played-vs-local-state-unplayed-however-due-to-the-remote-item-date-date-being-older-than-the-last-backend-sync-date-date-it-was-not-considered-as-valid-state

please confirm

jiggyjigsj commented 4 months ago

TBH, its most likely the issue you mentioned. Unfortunately, I'll need to reconfigure my networking to allow calls out from Jellyfin to watchstate. They are running in 2 different sites, so it gets a tiny bit tricky to make a call-out to the service.

Feel free to close this issue as you push out the error in log issue.

Thank you so much for the prompt response.