GoWatchIt does not appear to query metadata after receiving and decoding Plex webhook

openscallion commented 6 months ago

Describe the bug GoWatchIt does not complete querying of audio information, and consequently does not locate or set any ezBEQ filter.

After receiving a Plex webhook, nothing happens (either in logs or elsewise).

To Reproduce Steps to reproduce the behavior:

Play or pause movie in Plex.
Webhook is received by GoWatchIt, but no further action is taken or errors shown.

Expected behavior Metadata decoded and filter selected and loaded.

Configuration Attached. I have cleared the player/user filters during debug.

Debug logs EXCERPT: time="03-11-2024 04:12:15" level=info msg="Starting server on port 9999" time="03-11-2024 04:13:40" level=debug msg="decoding payload" time="03-11-2024 04:13:40" level=debug msg="decodeWebhook: Received event: media.play" time="03-11-2024 04:13:40" level=info msg="Got a request from UUID: redacted" time="03-11-2024 04:13:40" level=debug msg="ProcessWebhook: Media type is: movie" time="03-11-2024 04:13:40" level=debug msg="ProcessWebhook: Media title is: Arrival"

...then nothing until the next webhook event. No additional lines appear in the SUPER_DEBUG log.

Info (please complete the following information):

OS: Unraid
Version: 2.3.2, but also on latest pr-58
Deployment method: docker

Additional context The GoWatchIt container does have access (and pings successfully) the Plex server. The IPs are whitelisted in the Plex server. ezBEQ devices and status appear to be recognized, and GoWatchIt does clear the ezBEQ filters properly when it restarts.

Just odd that I'm not seeing any meaningful (to me) log output as to what could be going on.

Thank you!!

iloveicedgreentea commented 4 months ago

What is your config like? can you post the output of /config

douginoz commented 3 months ago

This is a "me too" though I only just realized it. I posted comprehensive logs and description in the AVS forum thread last night but I'll put them here too.

History:

Last week I moved my HA instance to a docker container on my server.
I also had my MQTT server running inside HA but I've also moved that out to it's own docker instance.
I updated my config to point to the new mqtt server and checked that the url, username and password are correct in gowatchit
I also removed a couple of HA automations related to controlling the lights via the sensor created by GoWatchIt

Problem:

Profiles are not being loaded into BEQ and I'm not receiving notifications.
The gowatchit logs just show normal startup with one error (see below)
It connects to plex and ezbeq correctly
It notes when I start a movie in Plex, but that's all
It doesn't show anything after that. Nothing. Until the movie is stopped/paused.
My mqtt server is running, and mqtt explorer shows all the other mqtt messages flying around including those for devices used in Home Assistant.

Things I've checked:

I have both SUPER_DEBUG: 'true' and LOG_LEVEL: 'debug' set in my docker compose file
plex.tv/devices.xml shows the ID for my player, the same as in the gowatchit config.json and in the logs: a18xfm0un4vvkax4kcsbnoo8
changing the mqtt server url to "mqtt://192.168.1.20:1833" in config.json and restarting gowatchit briefly creates a single log entry in my mqtt server for 'theater/beq/profile'
changing it back to "http://192.168.1.20:1833/" doesn't create any further mqtt log entries
my mqtt server is the eclipse-mosquitto docker container, re-created to ensure latest version running
I've tried playing a dozen different big-name movies in plex - most of them should have a beq profile
the ezbeq service is running with no errors, and triggering reload checks of the catalog every few minutes
I monitor the ezbeq web page (http://192.168.1.20:8255/) and refresh it to see if any profiles get loaded - none do.

Further notes:

I don't have any Home Assistant automations currently using gowatchit. I have a single sensor defined in my HA mqtt.yaml file.
My HA configuration.yaml has a notify: service: mobile_app_moas_15_pro_max which matches the gowatchit notify endpoint
My HA mqtt integration has discovery enabled
My HA mqtt integration has "homeassistant" as the discovery prefix
My gowatchit mqtt topics all start with 'theater/'
All versions are most recent as of May 26 2024. Server is running Ubuntu 23.10.
The one error in the logs is: time="05-27-2024 09:10:39" level=error msg="Error on startup - unloading beq error connecting to topic - network Error : unknown protocol" func=github.com/iloveicedgreentea/go-plex/internal/handlers.PlexWorker Which seems to be an MQTT error.

Log and Config files:

(https://pastebin.com/RHrgu5Da) - gowatchit log file, from the startup of the docker instance to playing a movie in Plex and waiting a couple of more minutes: (https://pastebin.com/pschKTCS) - gowatchit config.json (https://pastebin.com/yLxWuxm8) - docker compose file: docker container re-created today to ensure freshness but it's the same as has been running for months (https://pastebin.com/PpWzBHxa) - eclipse-mosquitto mosquitto.conf file (https://pastebin.com/hq8ku7EB) - Home Assistant mqtt.yaml file - read in from configuration.yaml

I've mucked around for several hours on this and have made no progress. Hopefully someone can spot a problem!

douginoz commented 3 months ago

Found a problem with the code: The configuration web page, in the MQTT section, instructs: MQTT URL with port URL - "http://x.x.x.x:1883" <- Must have http://

That's not correct. It has to be tcp://

Changing it removes the error line in my log file

level=error msg="Error on startup - unloading beq error connecting to topic - network Error : unknown protocol" func=github.com/iloveicedgreentea/go-plex/internal/handlers.PlexWorker file="/go/src/app/internal/handlers/plex_handler.go:533"

But the main problem remains - nothing happens after the process webhook in plex.handler.

douginoz commented 3 months ago

Ok there's something really bizarre going on. If I change the Home Assistant token to something random and incorrect, there's no mention in the log files. In fact, if I disable HA, confirmed by restarting the gowatchit container after making the change in the web UI then reading the configuration.json from within a shell in the container and seeing:

"homeassistant": { "enabled": false, <<<< not enabled "pausescriptname": "", "playscriptname": "", "port": "8123", "remoteentityname": "", "stopscriptname": "", "token": "xxxxxeyJhb" <<<< incorrect token

Yet the log files produced after restarting gowatchit show:

time="05-28-2024 02:33:01" level=info msg="Started with HA enabled"

This log entry is definitely after restarting gowatchit, checking the config in the web ui, and checking the config file directly.

So.... is gowatchit even reading the config file at all?

douginoz commented 3 months ago

I found the problem. plex_handler.go does a case-sensitive comparison between a constant in the code ("Movie"), and the plex webhook metadata "type", which is "movie". Thus it's failing the comparison and no further actions take place:

decodedPayload.Metadata.Type was "movie" (all lowercase).
movieItemTitle was "Movie" (with an uppercase 'M').

The fix is to change: if decodedPayload.Metadata.Type == movieItemTitle || decodedPayload.Metadata.Type == showItemTitle

to

if strings.EqualFold(decodedPayload.Metadata.Type, movieItemTitle) || strings.EqualFold(decodedPayload.Metadata.Type, showItemTitle)

Alternatively, change the constant in plex_handler.go:

const (
    movieItemTitle = "Movie"
    showItemTitle  = "Show"

to match the exact case of the plex webhook output. Probably not a good idea.

It appears that the code was changed in the 2.3.2 version from "movie" to "Movie" intentionally. Perhaps Plex webhook got updated since then and now send "movie". Better to ignore case than chase changes.

iloveicedgreentea commented 3 months ago

Yes case should be ignored. I am in the middle of a rewrite with a lot of changes but I can update this in master when I get a chance and the docs. Thanks

douginoz commented 3 months ago

No worries. I made the change to the file and compiled locally and running it manually for now. I tried using the build.sh to generate a new dockerfile, which works, but when I try to then run the image it's missing some libraries. So I'll just wait for a next release. I'm curious why this should have broken though. I saw the change in the beta next release where you search for 'Movie' instead of 'movie'. Why did you change it? Did Plex change the metadata 'type' case recently? I'd have thought this would break gowatchit for everyone, not just a couple of us. Weird.

iloveicedgreentea commented 3 months ago

you can try to pull v2.3.3 should fix your issue

douginoz commented 3 months ago

tested... fixed! Many thanks. Give me a shout if you want more testing on anything.

2 minutes later... wait a moment...

douginoz commented 3 months ago

The logs show a new error. The BEQ profile is loaded when the movie starts and unloaded at pause/stop, but there's this error mixed in amongst everything. Note that the profile remains loaded regardless (I think):

time="06-02-2024 16:00:25" level=error msg="Error loading BEQ profile: error connecting to topic - network Error : dial tcp: lookup tcp on 127.0.0.53:53: server misbehaving" func=github.com/iloveicedgreentea/go-plex/internal/handlers.mediaPlay file="/go/src/app/internal/handlers/plex_handler.go:308"

This implies that there's a problem with my dns server, but there isn't. I checked /etc/resolv.conf within the gowatchit container and it's correct. I can ping it and google.com from inside the container as well, and outside it on the host.

The error is when connecting to topic - so this seems like an MQTT problem. I'll check my mqtt server oh wait the config file won't be correct... hang on, this is my mistake I think

douginoz commented 3 months ago

It's definitely not connecting to my mqtt server, which is working normally. There are no messages arriving from gowatchit. The mqtt configuration in gowatchit is correct.

Another strange thing is that I receive only the error notification on my phone via Home Assistant, not the successful loading message: Error: UNLOADING profile: error connecting to topic - network Error: dial tcp: lookup http on 127.0.0.53:53: server misbehaving -- Unsafe to play movies!

That's confusing - there's no error message for a failed 'Loading Profile' notification to HA, but I don't receive the message. But there's a failure message for the 'Unloading Profile'.

So it's clearly connecting to my HA, and clearly not connecting to my MQTT service, and still loading and unloading BEQ profiles correctly for all situations.

douginoz commented 3 months ago

https://pastebin.com/x95fbXBu - docker compose file used: sophie gowatchit_docker.yml https://pastebin.com/VHmb2Gaj - gowatchit config.json https://pastebin.com/pfQmnySX - docker container log files

douginoz commented 3 months ago

ezbeq_journalctl.log

This file is the output of 'journalctl -u ezbeq.service -b > ezbeq_journalctl.log' - the log of ezbeq running. It includes mostly activities before my current testing but you can match up the timestamps in the gowatchit logs, e.g. searching for 15:59:26 will show the log entries for when Doctor Strange was loaded.

It doesn't seem to be showing any errors, yet gowatchit is reporting the http error while handling the load an unload beq profiles.

douginoz commented 3 months ago

Found the problem. This might be my own doing so I'll apologise if so. I changed the MQTT URL from "tcp://192.168.1.20:1883" to "192.168.1.20:1883" and it all works. I'd tried changing it to "http://192.168.1.20:1883" with no luck.

iloveicedgreentea commented 3 months ago

v2.3.5 fixes this I was inserting the scheme in the code but now you will need to add the scheme (like tcp://) in your config

Later on I will make this more user friendly just have not had time

openscallion commented 2 months ago

Thank you @douginoz for being able to do a deep dive where I could not and @iloveicedgreentea for the fix! Working for me as well.

I will note that I now receive two instances of this error in logs, though it appears to succeed on the third attempt:

time="06-22-2024 15:33:25" level=debug msg="Error with request - Retrying Get \"http://EZBEQIP:8080/api/1/search?audiotypes=Atmos&years=2001&tmdbid=120&authors=aron7awol&authors=mobe1969&authors=kaelaria\": context deadline exceeded (Client.Timeout exceeded while awaiting headers)"

Waiting for both of these to pass delays the search for a BEQ by ~30 seconds which does make pausing/resuming from pause a little clumsy since it unloads and then needs nearly a minute to re-enable the BEQ. Would be nice to cache recent BEQs locally or have a recently used one "on deck" which can be quickly reloaded if the metadata matches.

Thank you again for this!

iloveicedgreentea / GoWatchIt