Hello Michael, bpa,
thanks for your replies and effort to help.
mherger wrote:
> Could you please see what happens without your ffmpeg transcoding and
> debug logging for player.streaming.remote enabled? What does the
> server.log say then?
Please find attached the requested log without transcoding with ffmpeg
from playback on my home Win10 ntb (with player.streaming.remote and
player.source categories selected).
Here are just some snippets regarding file opening, buffering and
"EndOfStream" statutes:
Code:
--------------------
[18-04-12 11:31:19.4333] Slim::Player::Song::getNextSong (229)
http://media.rozhlas.cz/stream/_audio/3959575.mp3
[18-04-12 11:31:19.4339] Slim::Player::StreamingController::_nextTrackReady
(737) 00:04:20:12:7b:07: nextTrack will be index 0
[18-04-12 11:31:19.4344] Slim::Player::StreamingController::_eventAction
(271) 00:04:20:12:7b:07: NextTrackReady in STOPPED-TRACKWAIT ->
Slim::Player::StreamingController::_Stream
[18-04-12 11:31:19.4348] Slim::Player::StreamingController::_Stream (1203)
Song queue is now 0
[18-04-12 11:31:19.4352] Slim::Player::StreamingController::_Stream (1206)
00:04:20:12:7b:07: preparing to stream song index 0
[18-04-12 11:31:19.4356] Slim::Player::Song::open (363)
http://media.rozhlas.cz/stream/_audio/3959575.mp3
(...)
[18-04-12 11:31:19.4506] Slim::Player::TranscodingHelper::getConvertCommand2
(446) Matched: mp3->mp3 via: -
[18-04-12 11:31:19.4510] Slim::Player::Song::open (408) Transcoder:
streamMode=I, streamformat=mp3
[18-04-12 11:31:19.4515] Slim::Player::Song::open (451) URL supports direct
streaming
[http://media.rozhlas.cz/stream/_audio/3959575.mp3->http://media.rozhlas.cz/stream/_audio/3959575.mp3]
[18-04-12 11:31:19.4522] Slim::Player::SongStreamController::new (31) live=1
[18-04-12 11:31:19.4533] Slim::Player::StreamingController::_Stream (1265)
00:04:20:12:7b:07: stream
[18-04-12 11:31:19.4606] Slim::Player::StreamingController::_Stream (1302)
Song queue is now 0
[18-04-12 11:31:19.4609] Slim::Player::StreamingController::_setPlayingState
(2357) new playing state BUFFERING
[18-04-12 11:31:19.4610]
Slim::Player::StreamingController::_setStreamingState (2366) new streaming
state STREAMING
[18-04-12 11:31:19.4612] Slim::Player::StreamingController::_eventAction
(303) 00:04:20:12:7b:07: NextTrackReady - new state BUFFERING-STREAMING
[18-04-12 11:31:19.4645] Slim::Player::StreamingController::_eventAction
(271) 00:04:20:12:7b:07: StatusHeartbeat in BUFFERING-STREAMING ->
Slim::Player::StreamingController::_NoOp
[18-04-12 11:31:19.4653] Slim::Player::StreamingController::_eventAction
(271) 00:04:20:12:7b:07: StatusHeartbeat in BUFFERING-STREAMING ->
Slim::Player::StreamingController::_NoOp
[18-04-12 11:31:19.4825] Slim::Player::StreamingController::_eventAction
(271) 00:04:20:12:7b:07: StatusHeartbeat in BUFFERING-STREAMING ->
Slim::Player::StreamingController::_NoOp
[18-04-12 11:31:19.4938] Slim::Player::StreamingController::_eventAction
(271) 00:04:20:12:7b:07: StatusHeartbeat in BUFFERING-STREAMING ->
Slim::Player::StreamingController::_NoOp
[18-04-12 11:31:19.5858] Slim::Player::Player::_buffering (1140) Buffering...
0 / 20480
[18-04-12 11:31:19.5863] Slim::Player::Player::_buffering (1141) +output...
1128952 / 10584000
[18-04-12 11:31:19.5911] Slim::Player::StreamingController::_eventAction
(271) 00:04:20:12:7b:07: StatusHeartbeat in BUFFERING-STREAMING ->
Slim::Player::StreamingController::_NoOp
[18-04-12 11:31:19.5917] Slim::Player::StreamingController::_eventAction
(271) 00:04:20:12:7b:07: StatusHeartbeat in BUFFERING-STREAMING ->
Slim::Player::StreamingController::_NoOp
[18-04-12 11:31:19.6848]
Slim::Player::StreamingController::playerTrackStarted (2180) 00:04:20:12:7b:07
[18-04-12 11:31:19.6854] Slim::Player::StreamingController::_eventAction
(271) 00:04:20:12:7b:07: Started in BUFFERING-STREAMING ->
Slim::Player::StreamingController::_Playing
[18-04-12 11:31:19.6858] Slim::Player::StreamingController::_setPlayingState
(2357) new playing state PLAYING
[18-04-12 11:31:19.6862] Slim::Player::StreamingController::_Playing (361)
Song 0 has now started playing
[18-04-12 11:31:19.6872] Slim::Player::StreamingController::_Playing (390)
Song queue is now 0
[18-04-12 11:31:19.6876] Slim::Player::StreamingController::_eventAction
(303) 00:04:20:12:7b:07: Started - new state PLAYING-STREAMING
[18-04-12 11:31:19.9319] Slim::Player::StreamingController::_eventAction
(271) 00:04:20:12:7b:07: StatusHeartbeat in PLAYING-STREAMING ->
Slim::Player::StreamingController::_CheckSync
[18-04-12 11:31:20.9629] Slim::Player::StreamingController::_eventAction
(271) 00:04:20:12:7b:07: StatusHeartbeat in PLAYING-STREAMING ->
Slim::Player::StreamingController::_CheckSync
(...)
[18-04-12 11:42:15.9479] Slim::Player::StreamingController::_eventAction
(271) 00:04:20:12:7b:07: StatusHeartbeat in PLAYING-STREAMING ->
Slim::Player::StreamingController::_CheckSync
[18-04-12 11:42:15.9974] Slim::Player::StreamingController::playerEndOfStream
(2266) 00:04:20:12:7b:07
[18-04-12 11:42:15.9980] Slim::Player::StreamingController::_eventAction
(271) 00:04:20:12:7b:07: EndOfStream in PLAYING-STREAMING ->
Slim::Player::StreamingController::_AutoStart
[18-04-12 11:42:15.9985]
Slim::Player::StreamingController::_setStreamingState (2366) new streaming
state STREAMOUT
[18-04-12 11:42:15.9989] Slim::Player::StreamingController::_eventAction
(303) 00:04:20:12:7b:07: EndOfStream - new state PLAYING-STREAMOUT
[18-04-12 11:42:16.0027] Slim::Player::StreamingController::_eventAction
(271) 00:04:20:12:7b:07: StatusHeartbeat in PLAYING-STREAMOUT ->
Slim::Player::StreamingController::_CheckSync
(...)
--------------------
I also checked playback on my work PC connected via ethernet to other
network and it behaves exactly in the same way. I just noticed the
following error message in the ffmpeg log which doesn't appear in the
logs from ffmpeg on my home ntb (this is just due to different versions
of ffmpeg i use on my home and work computers):
Code:
--------------------
C:\WinAPP\ffmpeg\bin>ffmpeg -loglevel trace -i
http://media.rozhlas.cz/stream/_audio/3959575.mp3 -f mp3 pipe:play | ffplay -i
pipe:play
ffmpeg version N-86723-g3b3501f Copyright (c) 2000-2017 the FFmpeg developers
(...)
[http @ 0000000000d66c20] Stream ends prematurely at 10190801, should be
56058880: 0.000 fd= 0 aq= 20KB vq= 0KB sq= 0B f=0/0
http://media.rozhlas.cz/stream/_audio/3959575.mp3: I/O error
[out_0_0 @ 000000000274df20] EOF on sink link out_0_0:default.
No more output streams to write to, finishing.
--------------------
Attached is also a complete ffmpeg log with -reconnect option
(<aphonia_ffmpeg (with -reconnect option).jpg>).
Finally, I decided to try to capture network packets (never done that
before) via the Network Shell (netsh) utility and noticed that a
"Missing Data" warning appears in the HTTP response of the Czech Radio
server, see attached images for MessageNumber 433 at the time
11:31:19.4302909 which coincides with opening of the file by LMS at
11:31:19.4356 (<MMA_Warning_properties.jpg> and
<MMA_Warning_all_fields.jpg>):
24915
I think these error/warning messages confirm your findings:
mherger wrote:
>
> After I've looked into this issue a little more, I wonder whether their
> server isn't mis-configured. I do understand that some tools work their
> way around it, while LMS doesn't. But still:
>
> - They don't return any range related header in the response
> - the Content-Length header of the response returns the size of the full
> file
> - we don't request a range, but the full file
>
> Despite these pieces of information the server would unexpectedly stop
> streaming after a fraction of the content length reported.
>
If so, I will ask the internet service of Czech Radio to fix it,
although I was told yesterday that "nothing has changed" on their stream
server.
Please let me know your thoughts.
aphonia
PS: Thanks bpa for your recent posts/analysis, I will try to think over
this, for the meantime...
+-------------------------------------------------------------------+
|Filename: aphonia_ffmpeg (with -reconnect option).jpg |
|Download: http://forums.slimdevices.com/attachment.php?attachmentid=24919|
+-------------------------------------------------------------------+
Home server and store: pCP 3.5.0 on RPi 3B in Pi Desktop (Element14)
with Toshiba 256GB mSATA SSD drive
SB player: *Classic* + Corda Headfive + Sennheiser HD555 | Advance
Acoustic MAP-105 + Focal JM.lab Chorus 706 S
SB players (kids): *Touch* + Advance Acoustic MAP-103 | *Radio White*
(Limited Edition)
SB remote control: Squeeze Control on Windows 10 mobiles
------------------------------------------------------------------------
aphonia's Profile: http://forums.slimdevices.com/member.php?userid=42513
View this thread: http://forums.slimdevices.com/showthread.php?t=108891
_______________________________________________
unix mailing list
[email protected]
http://lists.slimdevices.com/mailman/listinfo/unix
