Attempting to fix 738 #886

geoffoxholm · 2024-03-29T21:20:06Z

I'm trying to fix #738.

It looks like some apps (maybe just "Audible" at the moment) have a very rigid interpretation of the connection handshake, and abandon it if messages come out-of-order.

I'd love any feedback to help move this forward. I can step into the debugger, do whatever is needed to figure out how to fix the issue, though I'm new to the pychromecast repo.

geoffoxholm · 2024-04-08T00:35:32Z

I would appreciate some feedback on this. Is there a better approach I could try? Any tips would be appreciated, I'll give it a serious try.

pyproject.toml

emontnemery · 2024-08-30T20:30:28Z

pychromecast/socket_client.py

+        # When a new cast status is received, give Audible time to load
+        if status.app_id == "25456794":
+            self.logger.debug("Detected Audible connection. Sleeping for 1s")
+            time.sleep(1)


This is not really OK way to fix a race. Is there another message we can wait for instead?

i'm not sure. any ideas you have, or example code you can point me to? i'll try whatever i can.

Issue #738 talks about the Sirius XM app misbehaving, but your comment in the PR talks about Audible. Could you clarify the relationship between the two apps? Or are they the same?

Also, after going through the comments in #738, it's not fully clear to me what pychromecast does which offends the app so much that it terminates, only that adding a delay fixes the problem.

Have you been able to determine how the delay fixes it?

If you run pychromecast with debug enabled, it will dump out all messages sent to and received from the pychromecast, have you done that?

Also, I'm not sure how you've been debugging. But if you want a simple isolated test case, maybe this example script is enough to trigger (and debug) the problem:

python3 -m examples.simple_listener_example --cast 'Living room' --show-debug

Ah, there's already a comment in #738 about using the simple listener example to trigger the problem: #738 (comment)

If you could do that, but with the updated syntax as in my previous comment, both with and without your workaround, that would be really useful.

git switch master python3 -m examples.simple_listener_example --cast 'Garage speakers' --show-debug > workspace/master.std.txt 2> workspace/master.err.txt

master.err.txt
master.std.txt

git switch geoffoxholm:users/geoff/audible_debug python3 -m examples.simple_listener_example --cast 'Garage speakers' --show-debug > workspace/patch.std.txt 2> workspace/patch.err.txt

patch.err.txt
patch.std.txt

There's a jump in requestId in messages sent by pychromecast to the device which I can't explain. We only increment the requestId when calculating it here:

pychromecast/pychromecast/socket_client.py

Lines 855 to 856 in 449c0b5

request_id = self._gen_request_id()

data[REQUEST_ID] = request_id

Have you removed any lines from the logs?

Edit: Maybe it's ping messages being omitted from the log

To be sure, could you change here to log also the pings, both on master and your patch branch, and collect new logs:

pychromecast/pychromecast/socket_client.py

Lines 873 to 882 in 449c0b5

# Log all messages except heartbeat

if msg.namespace != NS_HEARTBEAT:

self.logger.debug(

"[%s(%s):%s] Sending: %s",

self.fn or "",

self.host,

self.port,

_message_to_string(msg, data),

)

pychromecast/pychromecast/socket_client.py

Lines 689 to 697 in 449c0b5

# debug messages

if message.namespace != NS_HEARTBEAT:

self.logger.debug(

"[%s(%s):%s] Received: %s",

self.fn or "",

self.host,

self.port,

_message_to_string(message, data),

)

git switch master git pull # make edits git diff > workspace/master.diff.txt python3 -m examples.simple_listener_example --cast 'Garage speakers' --show-debug > workspace/master.std.txt 2> workspace/master.err.txt

master.diff.txt
master.err.txt
master.std.txt

git stash # stash edits git switch users/geoff/audible_debug git stash pop # pop edits git diff master > workspace/branch.diff.txt python3 -m examples.simple_listener_example --cast 'Garage speakers' --show-debug > workspace/branch.std.txt 2> workspace/branch.err.txt

branch.diff.txt
branch.err.txt
branch.std.txt

Issue #738 talks about the Sirius XM app misbehaving, but your comment in the PR talks about Audible. Could you clarify the relationship between the two apps? Or are they the same?

They are different apps. In the end the issue with Sirius XM was "fixed" (avoided) when the app was redesigned. It seems the Audible app has a similar pathology to the one that was present in the Sirius XM app, but no longer is.

Hi @emontnemery,

Any insight from the last logs you requested from @geoffoxholm?

I also have similar problem and setup and would like to contribute so that Audible works when pychromecast is active on the same network.

I can test the changes and try to fix some logic.

As of now the sleep tricks works, but I understand in your judgement it wont ever be merged since it's an ugly trick to fix race condition.

What is the better way to handle this? To me this behaves like an app quirk,and should be handled as so.

geoffoxholm · 2024-10-13T14:46:34Z

I showed the logs to Chat GPT, and it says:

emontnemery · 2024-10-15T14:19:09Z

What Chat GPT is suggesting is what I had in mind too; the delay prevents some kind of overlap between outstanding requests.
Unfortunately, that theory is not backed up by the logs AFAICT, meaning the suggestion by the bot is just based on hallucinations.

emontnemery · 2024-10-15T14:39:22Z

Since the logs don't point to the delay preventing an overlap in requests or any other out-of-order issue, I think a delay is the best we can do in pychromecast.
We should try to make it more targeted though, we now sleep every time we get a status update which is not great.

Could you try this change instead of what's in the PR:

diff --git a/pychromecast/socket_client.py b/pychromecast/socket_client.py
index 1d8eac1..c3d911e 100644
--- a/pychromecast/socket_client.py
+++ b/pychromecast/socket_client.py
@@ -490,6 +490,14 @@ class SocketClient(threading.Thread, CastStatusListener):
         self.session_id = status.session_id

         if new_channel and self.destination_id is not None:
+            if (
+                any(namespace in self._handlers for namespace in self.app_namespaces)
+                and self.destination_id not in self._open_channels
+                and status.app_id == "25456794"
+            ):
+                self.logger.debug("Detected Audible app. Sleeping for 1s")
+                time.sleep(1)
+
             # If any of the namespaces of the new app are supported
             # we will automatically connect to it to receive updates
             for namespace in self.app_namespaces:

emontnemery · 2024-10-17T11:20:21Z

@aryasenna @geoffoxholm could you try the version I suggest in #886 (comment) ?

geoffoxholm · 2024-10-17T14:57:41Z

@emontnemery - yes, sorry, i will try it as soon as i can. thank you for the suggestion.

aryasenna · 2024-10-17T17:45:40Z

@aryasenna @geoffoxholm could you try the version I suggest in #886 (comment) ?

Thanks a lot for the response.

I've tested your proposed code on my HA install.
Your targeted if still detects Audible's new cast status just fine:

...

 if new_channel and self.destination_id is not None:
            if (
                any(namespace in self._handlers for namespace in self.app_namespaces)
                and self.destination_id not in self._open_channels
                and status.app_id == "25456794"
            ):
                self.logger.warning("Checking emontnemery patch")
                self.logger.warning("Detected Audible app. Sleeping for 1s")
                time.sleep(1)

             # If any of the namespaces of the new app are supported
             # we will automatically connect to it to receive updates
             for namespace in self.app_namespaces:


...

Logger: pychromecast.socket_client
Source: /usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py:500
First occurred: 7:35:39 PM (2 occurrences)
Last logged: 7:36:04 PM

Checking emontnemery patch

Logger: pychromecast.socket_client
Source: /usr/local/lib/python3.12/site-packages/pychromecast/socket_client.py:501
First occurred: 7:35:40 PM (2 occurrences)
Last logged: 7:36:05 PM

Detected Audible app. Sleeping for 1s

Audible plays fine on the target cast device (tested with Nest Hub and Chromecast Audio)

After checking the patch, I get your hesitancy, it's quite "ugly" to make sleep based on an app ID like this, but it works, and Audible is not so obscure if you see home-assistant/core#87387 (comment) 🤷🏾‍♂️

geoffoxholm · 2024-10-17T20:11:44Z

@aryasenna - thank you for checking. i have added you to my fork, so if you wish to push to the PR branch, please go ahead.

aryasenna · 2024-10-18T11:00:24Z

@emontnemery I integrated your code to the PR d418837

pychromecast/socket_client.py

emontnemery · 2024-10-20T08:27:23Z

@aryasenna You didn't try my exact suggestion, I meant for the delay to be moved inside the check for new channel.
Maybe reading the diff is not that easy, here's the complete new_cast_status method:

    def new_cast_status(self, status: CastStatus) -> None:
        """Called when a new cast status has been received."""
        new_channel = self.destination_id != status.transport_id

        if new_channel and self.destination_id is not None:
            self.disconnect_channel(self.destination_id)

        self.app_namespaces = status.namespaces
        self.destination_id = status.transport_id
        self.session_id = status.session_id

        if new_channel and self.destination_id is not None:
            # App quirk: If the Audible app is running, wait 1s after receiving cast status
            # before connecting to the media player channel. This is a workaround for
            # https://github.com/home-assistant-libs/pychromecast/issues/738
            if (
                any(namespace in self._handlers for namespace in self.app_namespaces)
                and self.destination_id not in self._open_channels
                and status.app_id == "25456794"
            ):

                self.logger.debug("Detected Audible connection. Sleeping for 1s")
                time.sleep(1)

            # If any of the namespaces of the new app are supported
            # we will automatically connect to it to receive updates
            for namespace in self.app_namespaces:
                if namespace in self._handlers:
                    self._ensure_channel_connected(self.destination_id)
                    for handler in set(self._handlers[namespace]):
                        handler.channel_connected()

emontnemery · 2024-10-20T08:29:29Z

Also, instead of the magic number, please add the app constant:

diff --git a/pychromecast/config.py b/pychromecast/config.py
index 9c9864e..ac5a6ac 100644
--- a/pychromecast/config.py
+++ b/pychromecast/config.py
@@ -22,6 +22,7 @@ APP_BBCIPLAYER = "5E81F6DB"
 APP_SHAKA = "07AEE832"
 APP_NRKTV = "3AEDF8D1"
 APP_NRKRADIO = "A49874B1"
+APP_AUDIBLE = "25456794"

…irk handling.

aryasenna · 2024-10-20T11:01:46Z

@emontnemery Sorry for the confusion. I basically updated the PR branch with the wrong code in d418837,

but when I did the test, the sleep() was definitely under if new_channel and self.destination_id is not None:

Just double-checked the current code running on my VM:

I can confirm with the current code Audible is working fine.

I fixed it on e05baea, and it includes the use of app constant, as you requested.

geoffoxholm · 2024-10-20T14:19:53Z

Thanks @aryasenna for following through on this. I have reviewed your changes locally, and have tested in my own environment and everything looks good to me.

as an extremely minor nit, the blank line after the conditional is unusual for this codebase.

aryasenna · 2024-10-21T15:47:31Z

OK @geoffoxholm, I've also removed the extra line break.

I hope @emontnemery finds this PR acceptable now,

emontnemery

Thanks a lot @geoffoxholm and @aryasenna 👍

emontnemery · 2024-10-27T07:56:37Z

Home assistant core PR: home-assistant/core#129251
Will land in Home Assistant core 2024.11.0

oxholm-adobe added 3 commits March 29, 2024 17:50

bumping build requirements for python 3.12

ee2a3a5

introduce a short sleep for audible

7a3284a

Merge branch 'master' into users/geoff/audible_debug

4ab1fad

geoffoxholm changed the title ~~Users/geoff/audible debug~~ Fix for 738 Mar 29, 2024

geoffoxholm changed the title ~~Fix for 738~~ Attempting to fix for 738 Mar 29, 2024

geoffoxholm changed the title ~~Attempting to fix for 738~~ Attempting to fix 738 Mar 29, 2024

emontnemery reviewed Aug 30, 2024

View reviewed changes

merging master reverting pyproject.toml

290ee84

Use more targeted approach to handle Audible quirk.

d418837

emontnemery reviewed Oct 20, 2024

View reviewed changes

pychromecast/socket_client.py Outdated Show resolved Hide resolved

Update pychromecast/socket_client.py

519fa65

Use constant for Audible app_id and correct the scope of Audible's qu…

e05baea

…irk handling.

Merge branch 'master' into users/geoff/audible_debug

1d2b52d

Remove line break after conditional to follow code style.

facfd41

emontnemery approved these changes Oct 27, 2024

View reviewed changes

emontnemery merged commit fdf7766 into home-assistant-libs:master Oct 27, 2024
1 check passed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Attempting to fix 738 #886

Attempting to fix 738 #886

geoffoxholm commented Mar 29, 2024 •

edited

Loading

geoffoxholm commented Apr 8, 2024

emontnemery Aug 30, 2024

geoffoxholm Aug 30, 2024

emontnemery Aug 31, 2024

emontnemery Aug 31, 2024 •

edited

Loading

geoffoxholm Aug 31, 2024

emontnemery Sep 4, 2024 •

edited

Loading

emontnemery Sep 4, 2024

geoffoxholm Sep 4, 2024

geoffoxholm Sep 4, 2024

aryasenna Oct 13, 2024 •

edited

Loading

geoffoxholm commented Oct 13, 2024

emontnemery commented Oct 15, 2024 •

edited

Loading

emontnemery commented Oct 15, 2024 •

edited

Loading

emontnemery commented Oct 17, 2024

geoffoxholm commented Oct 17, 2024

aryasenna commented Oct 17, 2024 •

edited

Loading

geoffoxholm commented Oct 17, 2024

aryasenna commented Oct 18, 2024

emontnemery commented Oct 20, 2024 •

edited

Loading

emontnemery commented Oct 20, 2024

aryasenna commented Oct 20, 2024 •

edited

Loading

geoffoxholm commented Oct 20, 2024

aryasenna commented Oct 21, 2024

emontnemery left a comment

emontnemery commented Oct 27, 2024

	request_id = self._gen_request_id()
	data[REQUEST_ID] = request_id

	# Log all messages except heartbeat
	if msg.namespace != NS_HEARTBEAT:
	self.logger.debug(
	"[%s(%s):%s] Sending: %s",
	self.fn or "",
	self.host,
	self.port,
	_message_to_string(msg, data),
	)

	# debug messages
	if message.namespace != NS_HEARTBEAT:
	self.logger.debug(
	"[%s(%s):%s] Received: %s",
	self.fn or "",
	self.host,
	self.port,
	_message_to_string(message, data),
	)

Attempting to fix 738 #886

Attempting to fix 738 #886

Conversation

geoffoxholm commented Mar 29, 2024 • edited Loading

geoffoxholm commented Apr 8, 2024

emontnemery Aug 30, 2024

Choose a reason for hiding this comment

geoffoxholm Aug 30, 2024

Choose a reason for hiding this comment

emontnemery Aug 31, 2024

Choose a reason for hiding this comment

emontnemery Aug 31, 2024 • edited Loading

Choose a reason for hiding this comment

geoffoxholm Aug 31, 2024

Choose a reason for hiding this comment

emontnemery Sep 4, 2024 • edited Loading

Choose a reason for hiding this comment

emontnemery Sep 4, 2024

Choose a reason for hiding this comment

geoffoxholm Sep 4, 2024

Choose a reason for hiding this comment

geoffoxholm Sep 4, 2024

Choose a reason for hiding this comment

aryasenna Oct 13, 2024 • edited Loading

Choose a reason for hiding this comment

geoffoxholm commented Oct 13, 2024

emontnemery commented Oct 15, 2024 • edited Loading

emontnemery commented Oct 15, 2024 • edited Loading

emontnemery commented Oct 17, 2024

geoffoxholm commented Oct 17, 2024

aryasenna commented Oct 17, 2024 • edited Loading

geoffoxholm commented Oct 17, 2024

aryasenna commented Oct 18, 2024

emontnemery commented Oct 20, 2024 • edited Loading

emontnemery commented Oct 20, 2024

aryasenna commented Oct 20, 2024 • edited Loading

geoffoxholm commented Oct 20, 2024

aryasenna commented Oct 21, 2024

emontnemery left a comment

Choose a reason for hiding this comment

emontnemery commented Oct 27, 2024

geoffoxholm commented Mar 29, 2024 •

edited

Loading

emontnemery Aug 31, 2024 •

edited

Loading

emontnemery Sep 4, 2024 •

edited

Loading

aryasenna Oct 13, 2024 •

edited

Loading

emontnemery commented Oct 15, 2024 •

edited

Loading

emontnemery commented Oct 15, 2024 •

edited

Loading

aryasenna commented Oct 17, 2024 •

edited

Loading

emontnemery commented Oct 20, 2024 •

edited

Loading

aryasenna commented Oct 20, 2024 •

edited

Loading