1.9.7.1237-armv6hf: Won't play short files and such with low bitrate or sampling rate (TTS)

[Moonbase59]

First, let me thank you for all your work keeping SqueezeLite alive and kicking – much appreciated!

For alerting purposes, I run a SqueezeLite 1.9.1237-armv6hf on a Pi Zero W, using Raspbian 10 "Buster" and a cheap USB DAC. uname -a shows

Linux signalpi1 4.19.97+ #1294 Thu Jan 30 13:10:54 GMT 2020 armv6l GNU/Linux

lsusb shows:

Bus 001 Device 002: ID 0d8c:0014 C-Media Electronics, Inc. Audio Adapter (Unitek Y-247A)

SqueezeLite is in /usr/bin/squeezelite and the SqueezeLite command invoked is:

squeezelite -o front:CARD=Device,DEV=0 -n signalpi1

My Logitech Media Server (LMS) info is:

Logitech Media Server Version: 7.9.2 - 1578996832 @ Tue Jan 14 12:15:02 CET 2020
Hostname: studio1
IP-Adresse des Servers: 192.168.170.32
Server-HTTP-Portnummer: 9000
Betriebssystem: Debian - DE - utf8
Plattformarchitektur: x86_64-linux
Perl-Version: 5.18.2 - x86_64-linux-gnu-thread-multi
Audio::Scan: 0.95
IO::Socket::SSL: 2.068
Datenbankversion: DBD::SQLite 1.34_01 (sqlite 3.7.7.1)
Anzahl erkannter Player: 4

In general, this setup plays music files through LMS just fine, also longer MP3 alerts through Home Assistant via an SSL connection (using a valid cert).

Problem 1: MP3 files with certain lower bitrates like 32 kbit/s or 64 kbit/s and also lower sampling rates like 22050 or 24000 don’t play. This might be a problem of the cheap DAC used, so let’s disregard this for now, although it is bad if I use Home Assistant’s Google TTS (generates 24000 Hz, 32 kbit/s, mono files).

Maybe I can fix this myself by letting LMS resample via custom-convert.conf. Anyone doing this already and able to give me a good commandline here? (My LMS still runs on Ubuntu Studio 14.04.)

Problem 2: Short MP3 files (like alert sounds or short messages) don’t play. Testing using a 44100 Hz, 128 kbit/s, stereo MP3 I found that it’ll play files longer than about 4 seconds just fine, but doesn’t play shorter ones, like 2-3s in length.

Any ideas on this? I seem to remember there was a problem with short files in between versions 1.7 and 1.86 or such, maybe this is back again?

For testing with Home Assistant, I use the "Services" menu with these entries:

• Service: media_player.play_media
• Entity: media_player.signalpi1
• Service data, YAML: entity_id: media_player.signalpi1 media_content_id: https://has1.mydomain.net/local/alerts/transmission-start.mp3 media_content_type: music

Results are the same when using LMS’ "Direct URL" feature.

Sample files attached: station-off.mp3 doesn’t play, transmission-start.mp3 does. The ZIP also includes a squeezelite.log generated using:

squeezelite -o front:CARD=Device,DEV=0 -n signalpi1 -d decode=sdebug &> squeezelite.log

For the log, I first played transmission-start.mp3, then station-off.mp3 using LMS’ "Direct URL" feature.

For transmission-started.mp3, the LMS Web UI shows the ID3, plays, and stops. For station-off.mp3, only the URI is shown and the seconds counter continues forever (until I press "Empty Playlist"), but no sound is played.

sample-files.zip

[ralph-irving]

If the squeezelite has RESAMPLE support then for the unsupported sample rates on the cheap usb DAC you can add -u E to the command line and squeezelite will resample the incoming stream to the closest supported rate of the DAC.

As a test try disabling the default mad mp3 decoder by adding -e mad to the squeezelite command line so the mpg123 decoder is used instead.

[Moonbase59]

Thanks for the hint, I was actually experimenting with -R hLX (since -R hLE didn’t work) but postponed it to diagnose the other problem first. Also, local resampling pushes the Pi Zero quite a lot (97% CPU initially, dropping to about 25%).

Tried

squeezelite -o front:CARD=Device,DEV=0 -n signalpi1 -u E -e mad -d all=debug

now, with exactly the same results. I used -d all=debug, maybe this is more helpful.

Interesting: Whenever I try to play the short station-off.mp3 file, I only get

[15:30:19.708828] decode_flush:237 decode flush
[15:30:19.711630] output_flush:435 flush output buffer

as a log result. Studying the logs, I also don’t see a GET or the like for this file. I wonder if it’s actually LMS messing something up here? You might want to talk to Michael Herger maybe.

I somehow suspect LMS treats this as a "radio stream" which has a minimum buffer time of 3 seconds in LMS, so maybe LMS doesn’t want to play it because it doesn’t deliver enough data? And thus doesn’t send a play request or the like?

Then again, the Google TTS message I was playing around with is 9 seconds long (mp3, 24000 Hz, mono, s16p, 32 kb/s) but also doesn’t play.

I’m using "Direct Streaming" since SqueezeLite fortunately has "CanHTTPS=1". My LMS might be too old to be able to proxy an SSL stream correctly and I won’t be able to upgrade to a newer Linux for some further weeks (currently Ubuntu Studio 14.04, Perl 5.18.2, although I upgraded IO::Socket::SSL from CPAN to v2.068). I still think LMS should forward the https: URI to SqueezeLite correctly …

squeezelite-mpg.log google-test-tts.mp3.zip

[ralph-irving]

Without LMS logs showing an issue there's nothing to be discussed with MH. The two attached mp3 files play fine for me using mad and mpg123 but they are both stereo, 44.1k and 320kbps CBR according to LMS.

[Moonbase59]

So you’re saying even the station-off.mp3 plays correctly in your LMS, with tags showing? (And yes, these are 320kbps CBR stereo 44.1k. The Google TTS is not.)

Is there some way to find out if LMS is secretly proxying and would you tell me your OS, LMS, Perl and IO::Socket::SSL versions?

[ralph-irving]

Yes, station-off.mp3 plays fine and shows the tags. LMS indicates the length is 1sec.

Logitech Media Server Version: 7.9.3 - r20748.abacf96 @ 1588078273 Hostname: lms Server IP Address: 192.168.1.222 Server HTTP Port Number: 9000 Operating system: Debian - EN - utf8 Platform Architecture: i686-linux Perl Version: 5.14.2 - i486-linux-gnu-thread-multi-64int Audio::Scan: 1.02 IO::Socket::SSL: 2.067 Database Version: DBD::SQLite 1.58 (sqlite 3.22.0)

LMS does not secretly proxy a stream that I'm aware, you have to enable proxying for the streaming method per player.

[Moonbase59]

Thanks. Even older Perl than I have, but quite current IO::Socket::SSL and new LMS.

I wonder if it’s a problem with my LMS setup, after all. Maybe MH or someone else can help diagnosing this on the LMS side. I’ll certainly try to find out more from the LMS logs.

Would there be a relatively simple way to ask SqueezeLite to play an URI, without having to learn all the Slim Protocol stuff? ;-) Just so that I could exclude either LMS or SqueezeLite from the list of suspects?

For diagnosis, would you recommend me setting up a PiCorePlayer on the Pi Zero? (Simple exclusion system …) This could be more easily done than setting up a new PC with LMS.

Also for diagnosis, would it help if I gave you the real https: links (privately) of the two MP3 files mentioned, so you could try to play them via https: as I do here?

[ralph-irving]

Yes, my lms system is still on debian 7. It works fine so I leave it alone. If it ain't broke and all that. I can't think of any benefit to setting up pcp for testing. It doesn't have the same tools available as a full raspbian. There's no easy way to have squeezelite play a url directly. If you can provide the actual mp3 files served by TTS I can sever them locally via https as a first step. You should be able to use wget to save them.

[Moonbase59]

Well I could also give you the real locations (https link using vaild cert) if you give me some means of sending these to you privately. Otherwise, the attached file google-test-tts.mp3 above was actually taken directly from a Google Translate call (and thus is "original", I just renamed it). Just don’t bother with pronounciation, I accidentally wrote English-language text with "de" language settings …

Regarding the other 2 MP3 files, I should probably have stated more clearly that these do play fine via LMS but not when using https. While the longer ones play fine via https, from the same server, same folder.

Using the same URI, the short files play fine from several OSes, Browsers, VLC, KODI, and others.

[Moonbase59]

Sent you a list of test links.

[ralph-irving]

Got it.

[ralph-irving]

This really looks like an LMS https issue. LMS never sends the slimproto start message strm s to squeezelite when the file is served via https whereas with http it does. Squeezelite never tries to connect to the https stream to play it. Your https station-off.mp3 url does NOT play on an SB3 nor a Radio. Therefore the issue is not specific to squeezelite AFAICT.

HTTP slimprotocol [15:27:13.908156] process:521 strm [15:27:13.908210] process_strm:274 strm command q [15:27:13.908226] sendSTAT:189 STAT: STMf [15:27:13.917952] process:521 audg [15:27:13.917984] process_audg:433 audg gainL: 2048 gainR: 2048 adjust: 1 [15:27:13.920043] process:521 strm [15:27:13.920079] process_strm:274 strm command s [15:27:13.920088] process_strm:344 strm s autostart: 3 transition period: 10 transition type: 0 codec: m [15:27:13.920097] sendSTAT:189 STAT: STMf [15:27:13.920201] sendSTAT:189 STAT: STMc [15:27:13.920212] process_strm:377 set fade mode: 0 [15:27:13.920417] process:521 audg [15:27:13.920431] process_audg:433 audg gainL: 2048 gainR: 2048 adjust: 1 [15:27:13.970017] sendRESP:220 RESP [15:27:13.972063] process:521 cont [15:27:13.972091] process_cont:391 cont metaint: 0 loop: 0 [15:27:14.045581] process:521 strm [15:27:14.045616] process_strm:274 strm command t [15:27:14.045625] sendSTAT:189 STAT: STMt [15:27:14.070256] sendDSCO:208 DSCO: 0 [15:27:14.086540] process:521 strm [15:27:14.086596] process_strm:274 strm command u [15:27:14.086611] process_strm:331 unpause at: 0 now: 1394614188 [15:27:14.086623] sendSTAT:189 STAT: STMr [15:27:14.122754] sendSTAT:189 STAT: STMd [15:27:14.122793] sendSTAT:189 STAT: STMt [15:27:15.123852] sendSTAT:189 STAT: STMs [15:27:15.123934] sendSTAT:189 STAT: STMt [15:27:16.001059] slimproto_run:709 output underrun [15:27:16.001104] sendSTAT:189 STAT: STMu

HTTPS slimprotocol: [15:31:03.465210] process:521 strm [15:31:03.465233] process_strm:274 strm command q [15:31:03.465249] sendSTAT:189 STAT: STMf [15:31:03.465373] process:521 setd [15:31:03.465516] process:521 setd [15:31:03.465668] process:521 aude [15:31:03.465804] process_aude:415 enable spdif: 1 dac: 1 [15:31:03.465963] process:521 audg [15:31:03.466099] process_audg:433 audg gainL: 2048 gainR: 2048 adjust: 1 [15:31:05.044986] process:521 strm [15:31:05.045023] process_strm:274 strm command t [15:31:05.045032] sendSTAT:189 STAT: STMt [15:31:10.001085] process:521 strm [15:31:10.001133] process_strm:274 strm command t [15:31:10.001147] sendSTAT:189 STAT: STMt [15:31:12.051787] process:521 strm [15:31:12.051826] process_strm:274 strm command q

This is the stream=debug output from squeezelite when station-off.mp3 is server using http the connection never happens when served via https.

[14:52:01.444350] stream_init:370 init stream [14:52:05.763970] _tcp_connect:486 connecting to 192.168.1.222:80 [14:52:05.764054] stream_sock:577 header: GET /amp/station-off.mp3 HTTP/1.0 Cache-Control: no-cache Connection: close Accept: / Host: lms.dap.ca User-Agent: iTunes/4.7.1 (Linux; N; Debian; i686-linux; EN; utf8) SqueezeCenter, Squeezebox Server, Logitech Media Server/7.9.3/r20748.abacf96 Icy-Metadata: 1

[14:52:05.851171] stream_thread:247 headers: len: 260 HTTP/1.1 200 OK Date: Fri, 15 May 2020 18:52:05 GMT Server: Apache/2.2.22 (Debian) Last-Modified: Thu, 14 May 2020 15:55:38 GMT ETag: "39e286-1336b-5a59dba52f280" Accept-Ranges: bytes Content-Length: 78699 Connection: close Content-Type: audio/mpeg

[14:52:05.951451] stream_thread:320 end of stream

[michaelherger]

@ralph-irving would the communication look differently for the longer files? @Moonbase59 said that the 4s+ files would play perfectly well.

@Moonbase59 would the short file stream if you enabled Proxied Streaming in LMS/Settings/Player/Audio/Streaming Method?

[philippe44]

Have you tried to set "network.protocol.slimproto" and "player.streaming.remote" logs to debug in LMS (not in the player) so see why the strm_s is never sent? I parsed StreamController and Squeezebox.m quickly and could not find an obvious reason, but that was a super quick look, so a server log would help.

[Moonbase59]

@ralph-irving Cheers for testing, much appreciated! Ralph, if there is any easy way for you, you may pass the "test-links.txt" file on to Michael and Philippe for them to test. Good find on the http: vs. https:!

@michaelherger Love that you still (!) care so much about LMS (which we love)! It seems my setup might be too old to do SSL via LMS properly (Ubuntu 14.04/Perl 5.18), really looking forward to test this with Ubuntu/Mint 20 (which unfortunately will take a few weeks).

The only output devices I could get to work for HomeAssistant alerts are KODI and SqueezeLite (probably because CanHTTPS=1 and direct streaming). LMS will play the longer ones to SqueezeLite but not to my Receiver or Radio. Although for some reason, when syncing the Receiver and SqueezeLite, both play the longer ones.

My gut feeling is that the player doesn’t ever get the play command sent because LMS treats remote audio files like a radio stream, which has a minimum buffer time of 3 seconds (at least you can’t set it below 3s in settings). For the short files, LMS UI also only shows the URI and keeps counting up the seconds (like on a radio stream) forever without ever starting playout. The longer files show the URI for a moment, then present the ID3 tag info and play.

I’ll try proxied streaming again later.

@philippe44 I’m also thinking logging stuff on the LMS would help, glad to check these later on.

[Moonbase59]

@ralph-irving Using -R hLE for local resampling seems to cure most of the "low bitrate" problems (my el-cheapo DAC only supports 44100 and 48000), although it pushes the Pi Zero a little. I think we might disregard problem 1 for now and concentrate on problem 2.

@michaelherger I might still like to find out how correct LMS resampling using custom-convert.conf works. I’d like to resample like mp3 mp3 squeezelite * only if a local or remote file’s bitrate was not 44100 or 48000 sample rate. Is that possible?

Reason: I plan to have a few cloud-free alerting devices (think Alexa-like boxes) using Raspberry Zeroes that will output audible alerts using pre-recorded MP3s and Home Assistant Google TTS messages, and also output visible alerts (8 LEDs) using MQTT and Python software I wrote. Some of these will even be sync’ed. Since my LMS runs 24/7 on a quite powerful machine, it might be better to have the load there (and process stuff only once) instead of having the poor Zeroes resample plus running my other software.

[Moonbase59]

I’m trying to get at the problem step-by-step. So I set network.asynchttp logging to debug and tried to play the files transmission-start.mp3 and station-off.mp3 via LMS’ Direct URL feature to the signalpi1 player (SqueezeLite).

Seems LMS is doing the right thing and able to read the MP3 data, although the short one still doesn’t play and shows the counting seconds. Also, I think, Home Assistant’s Python web server (which I use to serve up the MP3s) sucks regarding its content-length header data:

  "content-length" => 174_834,

The actual length is correct (174834 bytes MP3 body) but the underscore character is not.

EDIT: Just checked, headers are actually ok, it must be the decoding within LMS that shows it this way.

Here’s the log for transmission-start.mp3 (the one that plays):

[20-05-16 13:46:01.8102] Slim::Networking::Async::connect (108) Connecting to has1.xxxxxxxxxxxxxxxx.myfritz.net:443
[20-05-16 13:46:01.8884] Slim::Networking::Async::_async_connect (188) Slim::Networking::Async::Socket::HTTPS=GLOB(0xa7b25c8) => 43 connected, ready to write request
[20-05-16 13:46:01.8887] Slim::Networking::Async::write_async (218) Sending: [GET /local/alerts/transmission-start.mp3 HTTP/1.0
Connection: close
Cache-Control: no-cache
Accept: */*
Host: has1.xxxxxxxxxxxxxxxx.myfritz.net
User-Agent: iTunes/4.7.1 (Linux; N; Debian; x86_64-linux; DE; utf8) SqueezeCenter, Squeezebox Server, Logitech Media Server/7.9.2/1578996832
Icy-Metadata: 1

]
[20-05-16 13:46:01.9041] Slim::Networking::Async::HTTP::_http_read (418) Headers read. code: 200 status: OK
[20-05-16 13:46:01.9045] Slim::Networking::Async::HTTP::_http_read (419) bless({
  "accept-ranges" => "bytes",
  "cache-control" => "public, max-age=2678400",
  "content-length" => 174_834,
  "content-type" => "audio/mpeg",
  date => "Sat, 16 May 2020 11:46:02 GMT",
  "last-modified" => "Thu, 14 May 2020 15:55:38 GMT",
  server => "Python/3.7 aiohttp/3.6.1",
}, "HTTP::Headers")
[20-05-16 13:46:01.9179] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9189] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 13:46:01.9193] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9227] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9231] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9235] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 13:46:01.9237] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9265] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9268] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9275] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 13:46:01.9277] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9298] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9300] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9303] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 13:46:01.9306] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9311] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9313] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9320] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9322] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 13:46:01.9324] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9329] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9331] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9333] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9345] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9356] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9359] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9390] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9392] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 13:46:01.9395] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9410] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9413] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9415] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9417] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9419] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 13:46:01.9422] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9424] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9426] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:46:01.9444] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 13:46:01.9451] Slim::Networking::Async::disconnect (243) Close Slim::Networking::Async::Socket::HTTPS=GLOB(0xa7b25c8) => 43
[20-05-16 13:46:01.9483] Slim::Networking::Async::HTTP::_http_read_body (577) closing mode
[20-05-16 13:46:01.9485] Slim::Networking::Async::HTTP::_http_read_body (585) Body read

and here the one for station-off.mp3 (which doesn’t play):

[20-05-16 13:49:36.8952] Slim::Networking::Async::connect (108) Connecting to has1.xxxxxxxxxxxxxxxx.myfritz.net:443
[20-05-16 13:49:36.9456] Slim::Networking::Async::_async_connect (188) Slim::Networking::Async::Socket::HTTPS=GLOB(0xa62c3c8) => 43 connected, ready to write request
[20-05-16 13:49:36.9460] Slim::Networking::Async::write_async (218) Sending: [GET /local/alerts/station-off.mp3 HTTP/1.0
Connection: close
Cache-Control: no-cache
Accept: */*
Host: has1.xxxxxxxxxxxxxxxx.myfritz.net
User-Agent: iTunes/4.7.1 (Linux; N; Debian; x86_64-linux; DE; utf8) SqueezeCenter, Squeezebox Server, Logitech Media Server/7.9.2/1578996832
Icy-Metadata: 1

]
[20-05-16 13:49:36.9595] Slim::Networking::Async::HTTP::_http_read (418) Headers read. code: 200 status: OK
[20-05-16 13:49:36.9599] Slim::Networking::Async::HTTP::_http_read (419) bless({
  "accept-ranges" => "bytes",
  "cache-control" => "public, max-age=2678400",
  "content-length" => 78_699,
  "content-type" => "audio/mpeg",
  date => "Sat, 16 May 2020 11:49:37 GMT",
  "last-modified" => "Thu, 14 May 2020 15:55:38 GMT",
  server => "Python/3.7 aiohttp/3.6.1",
}, "HTTP::Headers")
[20-05-16 13:49:36.9608] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9638] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9662] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9667] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9671] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9674] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9709] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 13:49:36.9712] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9714] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9717] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9732] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9734] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9743] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 13:49:36.9745] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9754] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9761] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9764] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9766] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9768] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9775] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9778] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 13:49:36.9781] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9792] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9795] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9800] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9802] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9808] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9810] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9828] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 13:49:36.9830] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9840] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9843] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9849] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 13:49:36.9852] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [13163] bytes
[20-05-16 13:49:36.9854] Slim::Networking::Async::disconnect (243) Close Slim::Networking::Async::Socket::HTTPS=GLOB(0xa62c3c8) => 43
[20-05-16 13:49:36.9857] Slim::Networking::Async::HTTP::_http_read_body (577) closing mode
[20-05-16 13:49:36.9858] Slim::Networking::Async::HTTP::_http_read_body (585) Body read

So now for some further logging …

[Moonbase59]

I now enabled network.protocol.slimproto in addition. Here are the logs for above two files. "Our" SqueezeLite player is b8:27:eb:3f:91:91, just disregard messages to/from the other players.

As far as I can see, the MP3 is read but no player command ever given for the short file. Please advise what else I could log so we can find the fault.

station-off.log transmission-start.log

[Moonbase59]

@michaelherger When I set the SqueezeLite player to do proxied streaming, it won’t play any file served via https::

[20-05-16 15:07:29.2909] Slim::Player::Song::open (471) Warning: stream failed to open [https://has1.xxxxxxxxxxxxxxxx.myfritz.net/local/alerts/transmission-start.mp3].

But it will play local files from the database or via Direct URL if I use local file links like file:///home/matthias/Musik/…

Although I have a pretty old system here, I already updated IO::Socket::SSL to v2.068 from CPAN, in the hope that it’d improve things.

With my usual luck, we might look at two problems: LMS SSL due to old OS/Perl, plus another "short file via https" using direct streaming problem …

Anyways, lots of kudos to @ralph-irving for implementing CanHTTPS=1 and to you for encouraging him … I distinctly remember your message somewhere: "No players support https playout yet, YOU could change the game!" :-)

[ralph-irving]

I just finished re-testing this with latest LMS 8.0, openssl 1.1.1d and IO::Socket::SSL: 2.067.

The 4 second file...let's do it [20-05-16 09:01:06.6993] Slim::Player::Protocols::HTTP::canSeekError (815) bitrate unknown for: https://hostname.removed.net/local/alerts/transmission-start.mp3 [20-05-16 09:01:08.0237] Slim::Player::Squeezebox::stream_s (542) stream_s called: format: mp3 url: https://hostname.removed.net/local/alerts/transmission-start.mp3 [20-05-16 09:01:08.0257] Slim::Player::Squeezebox::stream_s (796) This player supports direct streaming for https://hostname.removed.net/local/alerts/transmission-start.mp3 as https://hostname.removed.net/local/alerts/transmission-start.mp3, let's do it.

The 2 second file...never tries to do it. This is the only matching log entry, no stream_s or mention of direct streaming.

[20-05-16 09:02:08.5906] Slim::Player::Protocols::HTTP::canSeekError (815) bitrate unknown for: https://hostname.removed.net/local/alerts/station-off.mp3

If I play the same 2 second file using http LMS plays it to squeezelite.

[20-05-16 09:21:56.0222] Slim::Player::Protocols::HTTP::canSeekError (815) bitrate unknown for: http://hebe2.dap.ca/amp/station-off.mp3 [20-05-16 09:25:12.8549] Slim::Player::Squeezebox::stream_s (542) stream_s called: format: mp3 url: http://hebe2.dap.ca/amp/station-off.mp3 [20-05-16 09:25:12.8569] Slim::Player::Squeezebox::stream_s (796) This player supports direct streaming for http://hebe2.dap.ca/amp/station-off.mp3 as http://hebe2.dap.ca/amp/station-off.mp3, let's do it.

Full log. server.log

@michaelherger @philippe44 I've emailed you both the live urls.

[ralph-irving]

Anyways, lots of kudos to @ralph-irving for implementing CanHTTPS=1 and to you for encouraging him … I distinctly remember your message somewhere: "No players support https playout yet, YOU could change the game!" :-)

Philippe44 implemented the CanHTTPS=1 support in squeezelite. I just helped refine it a bit to work on more OS platforms.

[Moonbase59]

Ok, so heartfelt thanks to @philippe44 as well! :-)

[Moonbase59]

Under the "live" server, in /local/test/google-tts-8s.mp3 is another Google TTS file (32 kbit/s, mono, 24000 Hz, 8s) which doesn’t play, albeit being 8s long. Same file plays fine locally (using file: URI through Direct URL in LMS).

So resampling in SqueezeLite works fine but LMS won’t play this over https:. Using VLC, KODI, Browsers, wget to play from the link works.

[philippe44]

Not that it is bringing a lot at this point, but

[20-05-16 14:19:01.3514] Slim::Networking::Async::connect (108) Connecting to [hidden]:443
[20-05-16 14:19:01.9521] Slim::Networking::Async::_async_connect (188) Slim::Networking::Async::Socket::HTTPS=GLOB(0xdb59a98) => 103 connected, ready to write request
[20-05-16 14:19:01.9534] Slim::Networking::Async::write_async (218) Sending: [GET /local/alerts/station-off.mp3 HTTP/1.0
Connection: close
Cache-Control: no-cache
Accept: */*
Host: [hidden]
User-Agent: iTunes/4.7.1 (Linux; N; Debian; armv7l-linux; EN; utf8) SqueezeCenter, Squeezebox Server, Logitech Media Server/7.9.3/1586752599
Icy-Metadata: 1

]
[20-05-16 14:19:02.1587] Slim::Networking::Async::HTTP::_http_read (418) Headers read. code: 200 status: OK
[20-05-16 14:19:02.1603] Slim::Networking::Async::HTTP::_http_read (419) bless({
  "accept-ranges" => "bytes",
  "cache-control" => "public, max-age=2678400",
  "content-length" => 78_699,
  "content-type" => "audio/mpeg",
  date => "Sat, 16 May 2020 21:19:02 GMT",
  "last-modified" => "Thu, 14 May 2020 15:55:38 GMT",
  server => "Python/3.7 aiohttp/3.6.1",
}, "HTTP::Headers")
[20-05-16 14:19:02.1628] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 14:19:02.1652] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 14:19:02.1669] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 14:19:02.3424] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 14:19:02.3448] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 14:19:02.3474] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 14:19:02.3494] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 14:19:02.5196] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 14:19:02.5221] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 14:19:02.5240] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [-1] bytes
[20-05-16 14:19:02.5264] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [16384] bytes
[20-05-16 14:19:02.5289] Slim::Networking::Async::HTTP::_http_read_body (514) Read body: [13163] bytes
[20-05-16 14:19:02.5308] Slim::Networking::Async::disconnect (243) Close Slim::Networking::Async::Socket::HTTPS=GLOB(0xdb59a98) => 103
[20-05-16 14:19:02.5322] Slim::Networking::Async::HTTP::_http_read_body (577) closing mode
[20-05-16 14:19:02.5328] Slim::Networking::Async::HTTP::_http_read_body (585) Body read

Shows that LMS is opening the URL successfully (to get the mp3 header) but the file is so small that the whole body is successfully received in the response to the first GET. I need to look at the server code to see if there is some findings to be made there

[philippe44]

another bit of information - I'll update this note but this is a recent addition that broke something. It does not work in latest 7.9.x but it does in 7.9.2 (need to see the exact date of the latest working version). I'll work on showing diffs

[philippe44]

I've left all my thoughts / discoveries, but the solution is at the end and some of the interim steps are erroneous. See [CRAP] comment at the end which is the proper explanation

I've located the issue - It comes from the move to Non-Blocking sockets for the HTTPS base (changes Async::Socket::HTTPS and Async.pm). I don't understand yet why, but I assume there is either some timeout or issues with the status of SSL sockets where the raw socket is writable/readable although the handshake has not finished yet, so in reality they are not ready yet

[edit]: here is the hypothesis

The scanURL has a special handling of HTTPS connection where it says that it cannot stream audio in // of getting metadata, so it needs to wait for ID3 to be acquired before launching the actual streaming

There is an onStream method used in read_body connected to streamAudioData. Normally, when streamAudioData has what it wants, it simply ends, but in the case of HTTPS, it must also callback the function that would normally have streamed audio in // of getting the metadata

The problem is that when the file is very small, we reach the end of the body and I think the peer disconnects (it's not a 1.1 connection, so no keep-alive) and the streamAudioData does not received it "last" call for the remaining ID3 data, so it does not have a chance to launch the actual audio streaming.

Now, when the file is large enough, the peer has not disconnected the HTTPS stream used for getting ID, so streamAudioData has the whole ID3 and can launch the actual streaming (see line ~845). That correlates perfectly the logs that I've taken and what we observed.

Now, I don't have yet a solution how to force calls to onStream when the peer disconnects and there is body data "unread"

[NB]: I don't understand why for NB sockets, _http_read_body is called when there is nothing to read, so it still processes and do callbacks and everything where I would tend to think that when there is nothing to read, either it should not be called or it should return immediately. It seems that when using NB, there is an awful amount of CPU wasted

[NB2]: continuing the monologue... exiting _http_read_body when there is nothing to read solves the issue, but I think it's just a scheduling "chance", i.e. streamAudioData is not called all the time so it receives the whole ID before the peer disconnects and then it's able to launch the actual streaming. Otherwise, so much time is wasted in streamAudioData numerous calls that the peer's socket disconnection is handled before streamAudioData has finished

[CRAP]: I think I got it. The issue is induced by NB sockets that induces calls to _http_read_body with nothing in it. The streamAudioData has a "first" time call where it looks for ID3 and sets the expected "real" ID3 length from that. Well ... if the first call is made with no length, we are doomed because "first" is set forever (for that session), we don't look for ID3 because we have no data, so we don't set the expected length and we wait for the "default" 128kB of data that never arrive ... except if the file is large enough. In all cases, we never got the ID3, BUT, at least if the file is large enough, we go to the bottom of streamAudioData with 128kB and stream happens ...

Ouf ...

So, I'm waiting for the wiser advices. What should we do? Change only streamAudioData or change _http_read_body as well or change the caller of _http_read_body so that it is called only when there is some actual data on the socket, in NB/HTTPS case (see CPAN::Net::HTTPS::NB.pm). My opinion is to change at least _http_read_body and streamAudioData, but I feel (as an embedded developer) that saving the CPU used by the constant callback would be better

[michaelherger]

Thanks guys - and sorry for the silence... I'll try to follow up on this discussion and @philippe44 's patch later today. Thanks again!

[Moonbase59]

Thanks again, guys, for investigating this—you all simply rock!

Without looking at the server code, here are some – possibly unrelated – ideas to probably check:

1. When starting out with this Home Assistant + TTS + LMS adventure, I always had the impression that TTS messages were chopped off at the end. At that time, I suspected HA’s TTS integration but maybe it’s just one of these typical mistakes we programmers make—having a (buffer) counter somewhere that is off by one?

   That could explain three problems: a) short files don’t work, b) longer files cut off, c) not "seeing" ID3 tags when they’re at the end of the file.

2. According to the logs, clients advertise they can accept ICY metadata. This is fine for streaming but we don’t get any ICY metadata in files. Just mentioning this because I see _http_read_body munching along in 16384 byte chunks which is a very common ICY metaint.

3. MP3 files can have their ID3 tags at either the start or the end of a file. There could even also be a Lyrics2 tag. (I’m sure I don’t use that in the test files.)

4. Maybe I messed something up updating IO::Socket::SSL to v2.068 from CPAN on a system that had v1.something before?

5. Regarding "expected length", let me kindly remind you of the content-length with an underscore in it. Don’t know if it’s related to anything, though.

[philippe44]

I’ve submitted a patch for LMS that fixes the issue. I can now play successfully your 3s files

[Moonbase59]

So should I manually implement the diffs of https://github.com/Logitech/slimserver/pull/339 to further help testing, or wait until the PR gets accepted and a version update can be done using the regular means?

The modules are in /usr/share/perl5/Slim/… on my system.

EDIT: Well, I’m too impatient :rofl: Applied your PR manually (line numbers were different in my Remote.pm) and guess: All test files work, Google TTS voice works via Home Assistant to the SqueezeLite player!

Hooray, and many many thanks!

[ralph-irving]

I patched my 7.9.3 and 8.0 as well and can confirm that the files play via https as well. Thank you!

[Moonbase59]

Next step: Find out why they still don’t play …

a) on my studio1 SqueezeLite (v1.9.6-1198, on Ubuntu Studio 14.04.6) when this player is sync'ed to my Receiver. (Works if unsync’ed.) b) on my Receiver c) on my Radio (displays "Problem: Verbindung zum Server nicht möglich für: Transmission started von Computer")

Tried with direct streaming and proxied streaming for Receiver and Radio. Didn’t try the Controller for playout yet (battery empty and power adaptor broken).

[20-05-17 19:03:02.3726] Slim::Player::Protocols::HTTPS::new (37) Couldn't create socket binding to  with timeout: 15 - Keine Route zum Zielrechner
[20-05-17 19:03:02.3731] Slim::Player::Song::open (471) Warning: stream failed to open [https://has1.xxxxxxxxxxxxxxxx.myfritz.net/local/alerts/transmission-start.mp3].

Additionally: Trying to output the low-bitrate Google TTS file to the Radio/Receiver shows the URI in the UI, counting up seconds, no playout, as before.

Probably some resampling needed in custom-convert.conf, after all? Don’t know what the original Logitech devices can handle.

Sorry Ralph, this isn’t a SqueezeLite problem anymore, but we’ve so far collected all info here, so hope you excuse if we follow up here …

[philippe44]

Did you apply patches on remote.pm and Async::HTTP.pm? On my Boom & Radio, the 3s file works

[mherger]

Thanks @philippe44! I've merged your PR and will merge forward to 8.0 in a minute.

[mherger]

@Moonbase59 - I tested every single stream from your test file and all of them worked on Radio and Squeezeplay.

[Moonbase59]

@philippe44 Yes. I stopped LMS service, modified the two files manually (as I said, my Remote.pm had different line numbers), and restarted LMS service.

@mherger Thanks for testing.

Let’s compare systems/LMS’s? I somehow suspect we’ve fixed one problem but there seems still to be a problem with my LMS accessing https. When I use direct streaming, my SqueezeLites work (but none of the others), when I use proxied streaming, none work (over https).

Anything I could test, log or update?

Thinking out loud … Good to know that it works from your end, accessing my server. Maybe it makes a difference that you are outside while I of course sit inside my network and try to access the files via the "outside address". Then again, my router usually does all this correctly (NAT’ing IPv4, also offering an IPv6 address) and I use a valid Let’s Encrypt cert. Plus, other software like KODI, VLC, browsers, wget, etc. can access the files just fine.

What’s odd: My Radio actually shows the ID3 info ("Transmission started" = ttle, "Computer" = artist) in the error message where it tells me it can’t connect to the server. So something must have already read at least part of the file …

Just tried a wget again, it seems to be offered both IPv6 and IPv4 addresses, can’t connect to IPv6, re-negotiates for the IPv4 address and gets the file. Does that help in any way?

$ wget https://has1.xxxxxxxxxxxxxxxx.myfritz.net/local/alerts/transmission-start.mp3
--2020-05-17 22:14:48--  https://has1.xxxxxxxxxxxxxxxx.myfritz.net/local/alerts/transmission-start.mp3
Auflösen des Hostnamen »has1.xxxxxxxxxxxxxxxx.myfritz.net (has1.xxxxxxxxxxxxxxxx.myfritz.net)«... 2003:xx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx, xxx.xxx.xx.x
Verbindungsaufbau zu has1.xxxxxxxxxxxxxxxx.myfritz.net (has1.xxxxxxxxxxxxxxxx.myfritz.net)|2003:xx:xxxx:xxxx:xxxx:xxxx:xxxx:xxxx|:443... fehlgeschlagen: Keine Route zum Zielrechner.
Verbindungsaufbau zu has1.xxxxxxxxxxxxxxxx.myfritz.net (has1.xxxxxxxxxxxxxxxx.myfritz.net)|xxx.xxx.xx.x|:443... verbunden.
HTTP-Anforderung gesendet, warte auf Antwort... 200 OK
Länge: 174834 (171K) [audio/mpeg]
In »»transmission-start.mp3«« speichern.

100%[====================================================================================================================================================================================================>] 174.834     --.-K/s   in 0,07s   

2020-05-17 22:14:51 (2,42 MB/s) - »transmission-start.mp3« gespeichert [174834/174834]

This test was done on Ubuntu 14.04, my SqueezeLite 1.9.6 player runs on the same system, my SqueezeLite 1.9.7 player on a current Raspbian "Buster". I wonder what might be the cause, and which IP version your experiments used.

[michaelherger]

Please provide full server.log for an attempt to stream using proxied streaming (player.source and whatever you enabled before). You have a "no route to server" error ("Keine Route zum Zielrechner"). Would be interesting to see what LMS is trying to do there.

[Moonbase59]

So I used the transmission-start.mp3 file again on the SqueezeLite player b8:ca:3a:bd:7c:26, having it set to proxied streaming and debug logging on for: network.asynchttp, network.protocol.slimproto and player.source:

server.log

I wonder if any of you would get errors when pinging some of my servers from the "outside" (provided you have IPv6):

ping has1.xxxxxxxxxxxxxxxx.myfritz.net
ping6 has1.xxxxxxxxxxxxxxxx.myfritz.net

ping studio1.xxxxxxxxxxxxxxxx.myfritz.net
ping6 studio1.xxxxxxxxxxxxxxxx.myfritz.net

Maybe it is some IPv6 routing quirk, after all. Unfortunately, I’m not really an expert regarding IPv6. I use an AVM Fritz!Box 7490, get a /56 prefix from my provider, and use AVM’s "MyFritz" (DynDNS-like) feature because that seemed the only one to correctly handle IPv4 and IPv6. IPv6 port sharing for the "has1" machine is set up (tcp/443), as well as NAT’ing it for IPv4.

Then again, even with the routing error, why can "the others" access and play the file?

[Moonbase59]

Here’s another one, trying to output the same file to an actual (Logitech) Receiver unit 00:04:20:16:e7:bb, which is set to direct streaming:

server.log

Seems LMS declines direct streaming, decides for proxied. The Web UI shows the ID3 and looks like playing (shows seconds elapsed and progress bar, returns to paused afterwards), but no sound.

For verification: Playing same file through a file link (file:///home/matthias/Musik/Today/Matze/ansagen/transmission-start.mp3) works fine.

[Moonbase59]

Must have something to do with the IPv6 "no route to server": I’ve temporarily disabled the "outside" IPv6 and everything starts working.

Since this is of course not a permanent solution (many nowadays have only IPv6), the question arises how LMS handles situations in which more than one server address is presented via DNS (which can be one or more IPv4 or IPv6 addresses, or a mixture of both as in my case).

[mherger]

I think it's time to start a new issue with your latest finding.

[Moonbase59]

What do you suggest? https://github.com/Logitech/slimserver/issues ?

Btw, found the reason for IPv6 "no route to host": Home Assistant is currently only single-stack (IPv4 or IPv6) but it is used to serve up the alert messages. Which, in my dual-stack infrastructure here, leads to https://has1.xxxxxxxxxxxxxxxx.myfritz.net/local/… links being advertised by DNS as both IPv6 and IPv4 address, but only IPv4 functioning.

Live and learn …

So I tend to have this closed over here, and THANK YOU all very very much for your patience in investigating this complex multi-problem matter with me!

[Moonbase59]

Hmmm. Sorry guys, need to re-open. In short: alerts from https server work, generated TTS files don’ŧ because transcoder wants an "R" entry in convert.conf.

To get rid of the other problem (dual-stack IPv4/IPv6) for now, I modified my Home Assistant server and my router/DynDNS to only accept (and propagate) an IPv4 address for has1.xxxxxxxxxxxxxxxx.myfritz.net. You should be able to verify that using dig, nslookup -q=AAAA, ping6 or the like.

For some reason unknown to me, after so many restarts, LMS now started talking to mysqueezebox.com again, which I think it didn’t in all the previous tests. Maybe a coincidence, just wanted to let you know.

For some reason now the alerts run fine (even the short ones, even on the Receiver and the Radio), but the Google TTS messages don’t. The latter are cached and served from a https://has1.xxxxxxxxxxxxxxxx.myfritz.net/api/tts_proxy/… URI by Home Assistant. As usual, they play on other devices if invoked by direct URI.

The log shows LMS using mode 'I' for the prerecorded alerts but wanting mode 'R' (remote) transcoding, which is nowhere defined in convert.conf (only 'IFB' is).

Here’s a log snippet for both the station-off.mp3 prerecorded alert as well as a generated TTS message: server.log

Unfortunately, the TTS MP3 files are only cached by HA for a certain amount of time (5 mins I guess), so probably no chance to get at them directly.

Well, it’s been a long day and night debugging, and I’m at my wit’s end for today. Maybe one of you has some ideas.

[michaelherger]

I still believe you're in the wrong place :-)

[michaelherger]

I wonder why LMS would want to re-encode an mp3 file? Did you change your transcoding settings? are you using a custom-convert file? Or are applying rate limiting?

[Moonbase59]

@michaelherger We could hop over but miss all the previous info and test, that’s mainly why I’m sticking on this — and it has to do with the original problem (albeit not being a SqueezeLite problem anymore, I agree).

I did try to set up a transcoding (upsamling to 44100/48000) before I opened this thread and before Ralph pointed me to SqueezeLite’s -R/-u feature, yes. But I never changed /etc/squeezeboxserver/convert.conf, only added a /etc/squeezeboxserver/custom-convert.conf and renamed it custom-convert.conv.sav because I couldn’t make it work. And of course I’ve restarted LMS a zillion times since then …

Maybe the Google TTS cache file gets served somehow differently from its original location than from the alerts folder? I copied one or two of those over to the alerts folder for you to be able to test, because HA’s caching would delete them after a while.

I’m baffled.

[Moonbase59]

Maybe this is why it wants to transcode: MPEG ADTS, layer III, v2?

matthias@studio1:~$ wget https://has1.xxxxxxxxxxxxxxxx.myfritz.net/api/tts_proxy/bd7fa4f45eb97eba3a8fcd40ecb6348591f56a87_de_-_google_translate.mp3
--2020-05-19 11:48:49--  https://has1.xxxxxxxxxxxxxxxx.myfritz.net/api/tts_proxy/bd7fa4f45eb97eba3a8fcd40ecb6348591f56a87_de_-_google_translate.mp3
Auflösen des Hostnamen »has1.xxxxxxxxxxxxxxxx.myfritz.net (has1.xxxxxxxxxxxxxxxx.myfritz.net)«... xxx.xxx.xx.xxx
Verbindungsaufbau zu has1.xxxxxxxxxxxxxxxx.myfritz.net (has1.xxxxxxxxxxxxxxxx.myfritz.net)|xxx.xxx.xx.xxx|:443... verbunden.
HTTP-Anforderung gesendet, warte auf Antwort... 200 OK
Länge: 13995 (14K) [audio/mpeg]
In »»bd7fa4f45eb97eba3a8fcd40ecb6348591f56a87_de_-_google_translate.mp3.1«« speichern.

100%[===================================================================================================================================================================================================>] 13.995      --.-K/s   in 0,01s   

2020-05-19 11:48:49 (1,34 MB/s) - »bd7fa4f45eb97eba3a8fcd40ecb6348591f56a87_de_-_google_translate.mp3.1« gespeichert [13995/13995]

matthias@studio1:~$ file bd7fa4f45eb97eba3a8fcd40ecb6348591f56a87_de_-_google_translate.mp3 
bd7fa4f45eb97eba3a8fcd40ecb6348591f56a87_de_-_google_translate.mp3: Audio file with ID3 version 2.4.0, contains: MPEG ADTS, layer III, v2,  32 kbps, 24 kHz, Monaural
matthias@studio1:~$ 

[Moonbase59]

Here’s a complete new server.log (I deleted the old server.log before to get a complete fresh log for you) with the following tests:

1. Start LMS (sudo service logitechmediaserver start).

2. Play a TTS message (from Home Assistant, https://has1.xxxxxxxxxxxxxxxx.myfritz.net/api/tts_proxy/454ac016bccc644f5077103c0a182f5cf3f062f9_de_-_google_translate.mp3) to the SqueezeLite b8:27:eb:3f:91:91. Results in UI showing the URI and counting up seconds until I empty the playlist. No sound.

3. Play a saved TTS message (https://has1.xxxxxxxxxxxxxxxx.myfritz.net/local/test/google-tts-8s.mp3) via DirectURL to the SqueezeLite b8:27:eb:3f:91:91. This has also been generated the same way using Home Assistant, I just copied it over from the cache folder and renamed it so you have an original to check. Shows ID3 in UI, plays.

4. Play the same message via DirectURL to my Receiver 00:04:20:16:e7:bb. Shows ID3 in UI, plays.

Both players are set to "Direct Streaming" again.

Sending you the complete log with debug enabled for network.asynchttp, network.protocol.slimproto, player.source because I’m at a complete loss now. Probably stared into log files for too many hours. Hopefully you can see something I miss.

server.log

N.B.: I managed to increase Home Assistant’s caching duration to 8 hours (instead of 5 minutes). So, using the "real" URLs, here is one at the original location https://has1.xxxxxxxxxxxxxxxx.myfritz.net/api/tts_proxy/8acbe86d8367e53dd83176e3fe391df7ae102c46_de_-_google_translate.mp3 that should be valid for 8 hours from now. I also made a copy of this under https://has1.xxxxxxxxxxxxxxxx.myfritz.net/local/test/google-tts-test.mp3 so you could observe any differences.