search

KoljaWindeler / ytube_music_player

YouTube music player for homeassistant
335 stars 52 forks source link

Next song takes 30 seconds or more at Sonos #144

Closed Stephan296 closed 2 years ago

Stephan296 commented 2 years ago

I use your component with a Sonos Play 5. When i click at next song in HA, it takes 30 seconds or more when it goes to the next song.

- self decoded URL via cipher
[E] async_get_url
- proxy loading time: 40.894732 sec
- forwarding url to player media_player.zolder
[E] async_get_track

Another example, when a song is finished and goes to the next song without i press on next:

[E] async_get_url
- proxy loading time: 63.14577 sec
- forwarding url to player media_player.zolder
[E] async_get_track
[E] async_sync_player
KoljaWindeler commented 2 years ago

Well .. how fast is your internet connection? It will download the complete song in proxy mode ... Take around 400ms here with 1gbps .. 40sec sounds like 10mbps?

Stephan296 commented 2 years ago

I have got a 300Mbps connection so thats not the problem (i think) I am gonna do speedtest at my machine. I come back with the result

From: Kolja Windeler @.> Sent: Monday, November 1, 2021 6:18:39 PM To: KoljaWindeler/ytube_music_player @.> Cc: Stephan296 @.>; Author @.> Subject: Re: [KoljaWindeler/ytube_music_player] Next song takes 30 seconds or more at Sonos (Issue #144)

Well .. how fast is your internet connection? It will download the complete song in proxy mode ... Take around 400ms here with 1gbps .. 40sec sounds like 10mbps?

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHubhttps://github.com/KoljaWindeler/ytube_music_player/issues/144#issuecomment-956425088, or unsubscribehttps://github.com/notifications/unsubscribe-auth/ADJA237TFSZ5AM4JZEPOKS3UJ3DW7ANCNFSM5HEJCXSA. Triage notifications on the go with GitHub Mobile for iOShttps://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Androidhttps://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

Stephan296 commented 2 years ago

I have test it multiple times but it's around 250 / 300 Mpbs

KoljaWindeler commented 2 years ago

On that machine that runs Homeassistent?

Stephan296 commented 2 years ago

yes, also test it at another machine with the same problem.

KoljaWindeler commented 2 years ago

hm .. are you willing to modify the code? https://github.com/KoljaWindeler/ytube_music_player/blob/59f11a0926f8f760b7fab3b950668c3afc094c2d/custom_components/ytube_music_player/media_player.py#L1358 change it to self.log_me('debug', "- self decoded URL via cipher: "+_url) and download that URL .. I'd assume that it will take the same 40-60 sec but let's see

Stephan296 commented 2 years ago

i have got the next code at line 1358:

self.log_me('debug',"[S] play_media, media_type: "+str(media_type)+", media_id: "+str(media_id))
Stephan296 commented 2 years ago

any idea to make improvement?

KoljaWindeler commented 2 years ago

Hmm I wonder why your line look different? Are you running the latest version? Have you installed it via HACS?

Stephan296 commented 2 years ago

I have installed the latest version by HACS. Just again, also with a complete new installation i have got the same problem. The problem is the proxy, thats for sure. When i use the url who reports in the logging, my system downloaded it within a second.

KoljaWindeler commented 2 years ago

Hm .. ok .. so the section of the code that downloads the file is on line https://github.com/KoljaWindeler/ytube_music_player/blob/59f11a0926f8f760b7fab3b950668c3afc094c2d/custom_components/ytube_music_player/media_player.py#L1223 and line 1231/1232 will write the report ... You could copy the two lines (1231/1232) between every step from 1223 to 1227 .. and thus end up with 4 debug times to check which line causes the most time .. just as an idea

Stephan296 commented 2 years ago
KoljaWindeler commented 2 years ago

So what code is before the fist logged time? Only await self.hass.async_add_executor_job(urlopen, _url) ?

Stephan296 commented 2 years ago 
021-11-21 20:44:37 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_get_cipher [E]
2021-11-21 20:44:37 DEBUG (MainThread) [custom_components.ytube_music_player.const] - login without brand ID
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_check_api ... - no valid API, try to login ... YouTube Api initialized ok, version: 0.19.1 [E]
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_update_selects
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - playlist: input_select.ytube_music_player_playlist not found
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - playmode: input_select.ytube_music_player_playmode not found
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - playContinuous: input_boolean.ytube_music_player_playcontinuous not found
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - mediaPlayer: input_select.ytube_music_player_speakers not found
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - Source: input_select.ytube_music_player_source not found
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - Drop down for media player not found
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_update_remote_player(Input zolder/ current ) [E]
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - Choosing media_player.zolder as player
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_update_playlists
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - no playlist select field, exit
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [E] async_update_selects
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_update_playmode
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [E] async_update_playmode 2
2021-11-21 20:44:42 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [E] async_startup
2021-11-21 20:44:48 INFO (MainThread) [homeassistant.components.automation.sonos_fix_youtube_music_player] Sonos fix YouTube-Music player: Executing step call service
2021-11-21 20:44:48 ERROR (MainThread) [custom_components.ytube_music_player.media_player] START async_call_method
2021-11-21 20:44:48 ERROR (MainThread) [custom_components.ytube_music_player.media_player] paused_is_idle
2021-11-21 20:44:48 ERROR (MainThread) [custom_components.ytube_music_player.media_player] None
2021-11-21 20:44:48 ERROR (MainThread) [custom_components.ytube_music_player.media_player] Setting x_is_idle to State Paused
2021-11-21 20:44:48 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [E] async_call_method
2021-11-21 20:44:50 WARNING (MainThread) [homeassistant.components.switch] Updating adguard switch took longer than the scheduled update interval 0:00:10
2021-11-21 20:44:55 INFO (MainThread) [custom_components.hacs] Stage changed: HacsStage.RUNNING
2021-11-21 20:44:56 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_select_source(media_player.zolder)
2021-11-21 20:44:56 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_update_remote_player(Input media_player.zolder/ current media_player.zolder)
2021-11-21 20:44:56 ERROR (MainThread) [custom_components.ytube_music_player.media_player] no change [E]
2021-11-21 20:44:56 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - Choosing media_player.zolder as player
2021-11-21 20:44:56 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [E] async_select_source
2021-11-21 20:44:57 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] play_media, media_type: playlist, media_id: PLC800B9699743BD19
2021-11-21 20:44:57 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_prepare_play
2021-11-21 20:44:57 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_check_api [E]
2021-11-21 20:44:57 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_update_remote_player(Input / current media_player.zolder) [E]
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_get_cipher [E]
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [E] async_prepare_play
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] get_playlist(playlistId=PLC800B9699743BD19)
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - shuffle new tracklist
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] _tracks_to_attribute
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_update_extra_sensor [E]
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_update_extra_sensor [E]
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [E] _tracks_to_attribute
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] _play
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_get_track
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - Playing track nr 1 / 25
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_get_url
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_check_api [E]
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - try to find URL on our own
2021-11-21 20:44:59 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - self decoded URL via cipher
2021-11-21 20:45:04 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - Failed to get own(!) URL for track, further details below. Will not try YouTube method
2021-11-21 20:45:04 ERROR (MainThread) [custom_components.ytube_music_player.media_player] Traceback (most recent call last):
File "/usr/local/lib/python3.9/site-packages/urllib3/connection.py", line 174, in _new_conn
conn = connection.create_connection(
File "/usr/local/lib/python3.9/site-packages/urllib3/util/connection.py", line 73, in create_connection
for res in socket.getaddrinfo(host, port, family, socket.SOCK_STREAM):
File "/usr/local/lib/python3.9/socket.py", line 954, in getaddrinfo
for res in _socket.getaddrinfo(host, port, family, type, proto, flags):
socket.gaierror: [Errno -3] Try again
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/local/lib/python3.9/site-packages/urllib3/connectionpool.py", line 699, in urlopen
httplib_response = self._make_request(
File "/usr/local/lib/python3.9/site-packages/urllib3/connectionpool.py", line 382, in _make_request
self._validate_conn(conn)
File "/usr/local/lib/python3.9/site-packages/urllib3/connectionpool.py", line 1010, in _validate_conn
conn.connect()
File "/usr/local/lib/python3.9/site-packages/urllib3/connection.py", line 358, in connect
conn = self._new_conn()
File "/usr/local/lib/python3.9/site-packages/urllib3/connection.py", line 186, in _new_conn
raise NewConnectionError(
urllib3.exceptions.NewConnectionError: <urllib3.connection.HTTPSConnection object at 0x7f1019017df0>: Failed to establish a new connection: [Errno -3] Try again
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/usr/local/lib/python3.9/site-packages/requests/adapters.py", line 439, in send
resp = conn.urlopen(
File "/usr/local/lib/python3.9/site-packages/urllib3/connectionpool.py", line 755, in urlopen
retries = retries.increment(
File "/usr/local/lib/python3.9/site-packages/urllib3/util/retry.py", line 574, in increment
raise MaxRetryError(_pool, url, error or ResponseError(cause))
urllib3.exceptions.MaxRetryError: HTTPSConnectionPool(host='r4---sn-5hne6nzd.googlevideo.com', port=443): Max retries exceeded with url: /videoplayback?expire=1637545499&ei=u6GaYauUK6SH6dsP8beWqAM&ip=77.250.176.86&id=o-AEAWK77MeFA_jbwH_7yYiKIQmiIablpQY3seg-pnSGZk&itag=140&source=youtube&requiressl=yes&mh=sC&mm=31%2C29&mn=sn-5hne6nzd%2Csn-5hnekn7k&ms=au%2Crdu&mv=m&mvi=4&pl=18&ctier=A&pfa=5&gcr=nl&initcwndbps=1833750&hightc=yes&vprv=1&mime=audio%2Fmp4&ns=e_FFFC0y4WS9h30Wz9GGgEYG&gir=yes&clen=2611368&dur=161.309&lmt=1631966386013705&mt=1637523425&fvip=4&keepalive=yes&fexp=24001373%2C24007246&beids=24010694&c=WEB_REMIX&txp=5532434&n=recu_e7zG7xxdZQZ&sparams=expire%2Cei%2Cip%2Cid%2Citag%2Csource%2Crequiressl%2Cctier%2Cpfa%2Cgcr%2Chightc%2Cvprv%2Cmime%2Cns%2Cgir%2Cclen%2Cdur%2Clmt&lsparams=mh%2Cmm%2Cmn%2Cms%2Cmv%2Cmvi%2Cpl%2Cinitcwndbps&lsig=AG3C_xAwRAIgXF2D6zEvpEczHcAtmSQJhRlgUBvj8K_tQkvLjDKbL0MCIBxga6jEX1ToPyXTSvtLgqbFgpbdBMYeH4YwTzuI-e8Z&sig=AOq0QJ8wRAIga_oKzeePq7eN2V37eszLZGl89anHB6zbC-F5_67uCnUCIC8YmoLB_Ulv4qTo6mnBEOb5aqK8tHKpUo8f2UYtl_8n (Caused by NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x7f1019017df0>: Failed to establish a new connection: [Errno -3] Try again'))
During handling of the above exception, another exception occurred:
Traceback (most recent call last):
File "/config/custom_components/ytube_music_player/media_player.py", line 1370, in async_get_url
r = await self.hass.async_add_executor_job(requests.head, _url)
File "/usr/local/lib/python3.9/concurrent/futures/thread.py", line 52, in run
result = self.fn(*self.args, **self.kwargs)
File "/usr/local/lib/python3.9/site-packages/requests/api.py", line 102, in head
return request('head', url, **kwargs)
File "/usr/local/lib/python3.9/site-packages/requests/api.py", line 61, in request
return session.request(method=method, url=url, **kwargs)
File "/usr/local/lib/python3.9/site-packages/requests/sessions.py", line 542, in request
resp = self.send(prep, **send_kwargs)
File "/usr/local/lib/python3.9/site-packages/requests/sessions.py", line 655, in send
r = adapter.send(request, **kwargs)
File "/usr/local/lib/python3.9/site-packages/requests/adapters.py", line 516, in send
raise ConnectionError(e, request=request)
requests.exceptions.ConnectionError: HTTPSConnectionPool(host='r4---sn-5hne6nzd.googlevideo.com', port=443): Max retries exceeded with url: /videoplayback?expire=1637545499&ei=u6GaYauUK6SH6dsP8beWqAM&ip=77.250.176.86&id=o-AEAWK77MeFA_jbwH_7yYiKIQmiIablpQY3seg-pnSGZk&itag=140&source=youtube&requiressl=yes&mh=sC&mm=31%2C29&mn=sn-5hne6nzd%2Csn-5hnekn7k&ms=au%2Crdu&mv=m&mvi=4&pl=18&ctier=A&pfa=5&gcr=nl&initcwndbps=1833750&hightc=yes&vprv=1&mime=audio%2Fmp4&ns=e_FFFC0y4WS9h30Wz9GGgEYG&gir=yes&clen=2611368&dur=161.309&lmt=1631966386013705&mt=1637523425&fvip=4&keepalive=yes&fexp=24001373%2C24007246&beids=24010694&c=WEB_REMIX&txp=5532434&n=recu_e7zG7xxdZQZ&sparams=expire%2Cei%2Cip%2Cid%2Citag%2Csource%2Crequiressl%2Cctier%2Cpfa%2Cgcr%2Chightc%2Cvprv%2Cmime%2Cns%2Cgir%2Cclen%2Cdur%2Clmt&lsparams=mh%2Cmm%2Cmn%2Cms%2Cmv%2Cmvi%2Cpl%2Cinitcwndbps&lsig=AG3C_xAwRAIgXF2D6zEvpEczHcAtmSQJhRlgUBvj8K_tQkvLjDKbL0MCIBxga6jEX1ToPyXTSvtLgqbFgpbdBMYeH4YwTzuI-e8Z&sig=AOq0QJ8wRAIga_oKzeePq7eN2V37eszLZGl89anHB6zbC-F5_67uCnUCIC8YmoLB_Ulv4qTo6mnBEOb5aqK8tHKpUo8f2UYtl_8n (Caused by NewConnectionError('<urllib3.connection.HTTPSConnection object at 0x7f1019017df0>: Failed to establish a new connection: [Errno -3] Try again'))
2021-11-21 20:45:04 ERROR (MainThread) [custom_components.ytube_music_player.media_player] QDYDRA5JPLE
2021-11-21 20:45:04 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [E] async_get_url
2021-11-21 20:45:04 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - proxy loading time: 5e-06 sec
2021-11-21 20:45:05 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - proxy loading time: 0.182816 sec
2021-11-21 20:45:05 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - proxy loading time: 0.183655 sec
2021-11-21 20:45:55 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - proxy loading time: 51.013175 sec
2021-11-21 20:45:55 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - proxy loading time: 51.018573 sec
2021-11-21 20:45:55 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - proxy loading time: 51.018759 sec
2021-11-21 20:45:55 ERROR (MainThread) [custom_components.ytube_music_player.media_player] - forwarding url to player media_player.zolder
2021-11-21 20:45:55 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_update_extra_sensor [E]
2021-11-21 20:45:55 INFO (SyncWorker_12) [soco.plugins] Initializing SoCo plugin ShareLinkPlugin
2021-11-21 20:45:56 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [E] async_get_track
2021-11-21 20:45:56 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [E] play_media
2021-11-21 20:45:56 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_sync_player ... media_player.zolder: paused -> playing [E]
2021-11-21 20:46:11 ERROR (MainThread) [custom_components.ytube_music_player.media_player] [S] async_sync_player ... media_player.zolder [E]
Stephan296 commented 2 years ago

1222 untij 1237:

            if(self._proxy_url != "" and self._proxy_path != ""):
                p1 = datetime.datetime.now()
                t = (datetime.datetime.now() - p1).total_seconds()
                self.log_me('debug', "- proxy loading time: " + str(t) + " sec")                
                _proxy_url = await self.hass.async_add_executor_job(urlopen, _url)
                t = (datetime.datetime.now() - p1).total_seconds()
                self.log_me('debug', "- proxy loading time: " + str(t) + " sec")                
                _proxy_file = open(os.path.join(self._proxy_path, PROXY_FILENAME), 'wb')
                t = (datetime.datetime.now() - p1).total_seconds()
                self.log_me('debug', "- proxy loading time: " + str(t) + " sec")
                _proxy_url_content = await self.hass.async_add_executor_job(_proxy_url.read)
                t = (datetime.datetime.now() - p1).total_seconds()
                self.log_me('debug', "- proxy loading time: " + str(t) + " sec")                
                await self.hass.async_add_executor_job(_proxy_file.write, _proxy_url_content)
                t = (datetime.datetime.now() - p1).total_seconds()
                self.log_me('debug', "- proxy loading time: " + str(t) + " sec")
Stephan296 commented 2 years ago

A friend of my has also this problem and he has a 1000Mbit connection.

KoljaWindeler commented 2 years ago

Hi, I can now reproduce the issue ... no idea what changed .. but now I can work on it

KoljaWindeler commented 2 years ago

so .. the issue is that the download speed has dramatically reduced. I was able to download a song in <1sec .. more like 0.4 or so ... not all my downloads are running at 65-120kB/sec .. I'd assume the same applies to you. I ended up with download times somewhere in the range of 50 to 80 sec.

To be honest: this is quite a big problem. The only solution that I could image is to "stream download" the file .. like download chunks of 10kB at the time and write that to a file .. when we do that we could start the playback after ~500kB or so .. so after 4-8ish seconds .. still not great but better then 50-80

I'll see what I can come up with .. no promisses ..

KoljaWindeler commented 2 years ago

I can't find a good way to add this reliably .. at this point I'd recommend to switch to a chromecast

Stephan296 commented 2 years ago

Thx for your effort. The sound quality of a chromecast is nothing compares to a Sonos device. Too bad for me.

From: Kolja Windeler @.> Sent: Monday, December 13, 2021 7:32:28 AM To: KoljaWindeler/ytube_music_player @.> Cc: Stephan296 @.>; Author @.> Subject: Re: [KoljaWindeler/ytube_music_player] Next song takes 30 seconds or more at Sonos (Issue #144)

I can't find a good way to add this reliably .. at this point I'd recommend to switch to a chromecast

— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHubhttps://github.com/KoljaWindeler/ytube_music_player/issues/144#issuecomment-992150279, or unsubscribehttps://github.com/notifications/unsubscribe-auth/ADJA234QHXCHT73GFH5U6XLUQWHPZANCNFSM5HEJCXSA. Triage notifications on the go with GitHub Mobile for iOShttps://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675 or Androidhttps://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub.

KoljaWindeler commented 2 years ago

The other option that I see would be to improve the sonos integration so it can stream directly from the url without the proxy .. it's able to stream, but not from the yoututbe url. I've never figures out what the issue was. As I recall: streaming from a path without extension '.mp4' didn't work .. thats something that the author of the integration might be able to fix ..