search

philippe44 / LMS-Cast

Chromecast to LMS bridge
64 stars 10 forks source link

v0.2.0.1 fails with Android TV #2

Closed gdhgdhgdh closed 8 years ago

gdhgdhgdh commented 8 years ago

Hi - I found this plugin completely by accident while scrolling through 'Third Party Plugins' - thank you for putting this together!

I tried it with the Cast support built into my Philips PUT6400 TV (it runs Android TV 5.1) but have had no luck. I can see the TV in the list of Squeeze devices, and when I play a track, it switches OK to the ChromeCast screen, and shows the album art and track info OK.. but no sound.

I cracked out tcpdump to take a closer look. My LMS is at 10.0.0.252 with the TV at 10.0.0.39

22:48:43.484907 IP 10.0.0.39.38757 > 10.0.0.252.49152: Flags [P.], seq 1:422, ack 1, win 1369, options [nop,nop,TS val 3185245 ecr 457199018], length 421
GET /LMS2CAST/1c-5a-6b-b9-89-e1-idx-0.mp3 HTTP/1.1
Host: 10.0.0.252:49152
Connection: keep-alive
User-Agent: Mozilla/5.0 (Linux; Android 5.1; Build/LMY47D) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.90 Safari/537.36 CrKey/1.17.46918
Range: bytes=0-1
Accept: */*
Accept-Encoding: gzip, deflate
Accept-Language: en-GB
CAST-DEVICE-CAPABILITIES: {"bluetooth_supported":false,"display_supported":true}
22:48:43.485585 IP 10.0.0.252.49152 > 10.0.0.39.38757: Flags [P.], seq 1:260, ack 422, win 972, options [nop,nop,TS val 457199018 ecr 3185245], length 259
HTTP/1.1 416 Requested Range Not Satisfiable
SERVER: Linux/3.2.0-4-amd64, UPnP/1.0, Portable SDK for UPnP devices/1.6.19
CONNECTION: close
CONTENT-LENGTH: 70
CONTENT-TYPE: text/html

<html><body><h1>416 Requested Range Not Satisfiable</h1></body></html>

The logfile is:

Starting Squeeze2cast: /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/CastBridge/Bin/squeeze2cast-x86-64 -Z -I -f /var/log/squeezeboxserver/castbridge.log -x /var/lib/squeezeboxserver/prefs/castbridge.xml
[22:48:00.014715] main:1175 Starting squeeze2cast version: v0.2.0.1 (Feb 15 2016 @ 23:23:06)

[22:48:00.019089] main:1206 Buffer path /tmp
[22:48:00.035658] Initialize:807 UPnP init success - 10.0.0.252:49152
[22:48:15.079182] AddCastDevice:912 [0x6b2440]: adding renderer (Office TV)
[22:48:15.154128] CastConnect:380 [0x6b2440]: SSL connection opened [0xdc18d0]
[22:48:15.160561] slimproto_thread_init:1007 [0x652720] connecting to 10.0.0.252:3483
[22:48:15.162691] slimproto:885 [0x652720] connected
[22:48:15.162763] sendHELO:132 [0x652720] cap: Model=squeezelite,ModelName=SqueezeLite,AccuratePlayPoints=0,HasDigitalOut=0,MaxSampleRate=96000,pcm,aif,flc,mp3
[22:48:15.213073] process_strm:238 [0x652720] strm command s
[22:48:15.213184] process_strm:309 [0x652720], strm s autostart: 1 transition period: 10 transition type: 0 codec: m
[22:48:15.213209] sendSTAT:165 [0x652720]: STAT:[STMf] msplayed 0
[22:48:41.003824] CastStop:203 [0x6b2440]: Stop req w/o session or connect
[22:48:41.014591] CastStop:203 [0x6b2440]: Stop req w/o session or connect
[22:48:41.103452] process_strm:238 [0x652720] strm command s
[22:48:41.103516] process_strm:309 [0x652720], strm s autostart: 1 transition period: 10 transition type: 0 codec: m
[22:48:41.103526] sendSTAT:165 [0x652720]: STAT:[STMf] msplayed 0
[22:48:41.103674] sq_callback:262 [0x6b2440]: codec:m, ch:255, s:255, r:255
[22:48:41.191704] sq_get_metadata:583 [0x652720]: idx 0
    artist:a-ha
    album:Hunting High and Low
    title:Love Is Reason
    genre:Alternative
    duration:187.223
    size:0
    cover:http://10.0.0.252:9000/music/d5be518f/cover.jpg
[22:48:41.192007] CastLoad:142 [0x6b2440]: Queuing LOAD
[22:48:41.192022] sq_callback:305 [0x6b2440]: current URI set http://10.0.0.252:49152/LMS2CAST/1c-5a-6b-b9-89-e1-idx-0.mp3
[22:48:41.192044] sendSTAT:165 [0x652720]: STAT:[STMc] msplayed 0
[22:48:41.351631] CastSimple:177 [0x6b2440]: Queuing PLAY
[22:48:42.072173] process_strm:238 [0x652720] strm command u
[22:48:42.072289] process_strm:285 [0x652720] unpause at: 0 now: 1829094662
[22:48:42.072344] sendSTAT:165 [0x652720]: STAT:[STMr] msplayed 0
[22:48:43.282397] CastSocketThread:667 [0x6b2440]: Receiver launched
[22:48:43.485247] sq_get_info:677 [0x652720]: GetInfo /LMS2CAST/1c-5a-6b-b9-89-e1-idx-0.mp3 -2 audio/mpeg
[22:48:44.476793] ProcessQueue:519 [0x6b2440]: PLAY un-queued but no media session
[22:48:45.178183] AddCastDevice:912 [0x6b2ba0]: adding renderer (Living room)
[22:48:45.270537] CastConnect:380 [0x6b2ba0]: SSL connection opened [0xdc9130]
[22:48:45.276121] slimproto_thread_init:1007 [0x655708] connecting to 10.0.0.252:3483
[22:48:45.278858] slimproto:885 [0x655708] connected
[22:48:45.278958] sendHELO:132 [0x655708] cap: Model=squeezelite,ModelName=SqueezeLite,AccuratePlayPoints=0,HasDigitalOut=0,MaxSampleRate=96000,pcm,aif,flc,mp3

Is that Range: bytes=0-1 something you'd expect from a standalone ChromeCast device?

philippe44 commented 8 years ago

Normally, a chromecast device does and HTTP GET to the URI it is provided to get the actual audio data. So all seems to be good up to there but then I have no idea why it requests a byte range 0-1. Having said that, the webserver (UPnP tools) should call my callbacks and I don't think I refuse to serve such strange range. Can you please take a log with all logs enabled - it will be chatty but I'll where the reject comes from

gdhgdhgdh commented 8 years ago

Hi - apologies for the long delay in updating this.. I just tried playing the same track again but this time with -d all=debug passed:


Starting Squeeze2cast: /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/CastBridge/Bin/squeeze2cast-x86-64 -Z -I -f /var/log/squeezeboxserver/castbridge.log -d all=debug -x /var/lib/squeezeboxserver/prefs/castbridge.xml
[12:39:10.564719] main:1175 Starting squeeze2cast version: v0.2.0.1 (Feb 15 2016 @ 23:23:06)

[12:39:10.564860] decode_init:125 init decode, include codecs:  exclude codecs: 
[12:39:10.564884] main:1206 Buffer path /tmp
[12:39:10.583199] Initialize:807 UPnP init success - 10.0.0.252:49152
[12:39:10.583275] Initialize:831 WebServer enabled
[12:39:10.583290] Initialize:842 VirtualDir set for Squeezelite
[12:39:10.583301] Initialize:859 Callbacks registered for VirtualDir
[12:39:10.583883] UpdateMRThread:628 Begin Cast devices update
[12:39:25.612288] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[12:39:25.613141] UpdateMRThread:712 End Cast devices update 15029
[12:39:40.613450] UpdateMRThread:628 Begin Cast devices update
[12:39:55.723583] AddCastDevice:912 [0x6b2440]: adding renderer (Office TV)
[12:39:55.809788] CastConnect:380 [0x6b2440]: SSL connection opened [0x87e660]
[12:39:55.810126] SendCastMessage:265 [0x87e660]: Cast sending: {"type":"CONNECT"}
[12:39:55.810551] stream_thread_init:296 [0x652720] streambuf size: 2457600
[12:39:55.817111] output_mr_thread_init:780 [0x652720] init output media renderer
[12:39:55.817292] decode_thread_init:152 [0x652720]: init decode
[12:39:55.817439] discover_server:814 [0x652720] sending discovery
[12:39:55.819453] discover_server:843 [0x652720] got response from: 10.0.0.252:3483
[12:39:55.819558] slimproto_thread_init:1007 [0x652720] connecting to 10.0.0.252:3483
[12:39:55.819732] AddCastDevice:912 [0x6b2ba0]: adding renderer (Living Room Chromecast)
[12:39:55.821573] slimproto:885 [0x652720] connected
[12:39:55.821660] sendHELO:131 [0x652720] mac: 1c:5a:6b:b9:89:e1
[12:39:55.821683] sendHELO:132 [0x652720] cap: Model=squeezelite,ModelName=SqueezeLite,AccuratePlayPoints=0,HasDigitalOut=0,MaxSampleRate=96000,pcm,aif,flc,aac,mp3
[12:39:55.826178] process:562 [0x652720] strm
[12:39:55.826457] process_strm:241 [0x652720] strm command q
[12:39:55.826483] decode_flush:197 [0x652720]: decode flush
[12:39:55.826503] output_flush:858 [0x652720]: flush output buffer
[12:39:55.826553] sq_callback:247 [0x6b2440]: device off or not controlled by LMS
[12:39:55.827895] process:562 [0x652720] strm
[12:39:55.827952] process_strm:241 [0x652720] strm command q
[12:39:55.827971] decode_flush:197 [0x652720]: decode flush
[12:39:55.827990] output_flush:858 [0x652720]: flush output buffer
[12:39:55.828021] sq_callback:247 [0x6b2440]: device off or not controlled by LMS
[12:39:55.829965] process:562 [0x652720] setd
[12:39:55.830014] sendSETDName:226 set playername: Office TV
[12:39:55.831182] process:562 [0x652720] setd
[12:39:55.832060] process:562 [0x652720] aude
[12:39:55.832113] process_aude:446 [0x652720] on/off using aude 1
[12:39:55.832134] sq_callback:243 [0x6b2440]: device set on/off 1
[12:39:55.833084] process:562 [0x652720] audg
[12:39:55.833134] process_audg:473 [0x652720] (old) audg gainL: 46 gainR: 46
[12:39:55.928097] CastConnect:380 [0x6b2ba0]: SSL connection opened [0x87ed80]
[12:39:55.928428] SendCastMessage:265 [0x87ed80]: Cast sending: {"type":"CONNECT"}
[12:39:55.928883] stream_thread_init:296 [0x655708] streambuf size: 2457600
[12:39:55.934043] output_mr_thread_init:780 [0x655708] init output media renderer
[12:39:55.934220] decode_thread_init:152 [0x655708]: init decode
[12:39:55.934558] discover_server:814 [0x655708] sending discovery
[12:39:55.935476] discover_server:843 [0x655708] got response from: 10.0.0.252:3483
[12:39:55.935544] slimproto_thread_init:1007 [0x655708] connecting to 10.0.0.252:3483
[12:39:55.935679] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[12:39:55.936987] UpdateMRThread:712 End Cast devices update 15323
[12:39:55.938875] slimproto:885 [0x655708] connected
[12:39:55.938974] sendHELO:131 [0x655708] mac: 6c:ad:f8:70:0e:ef
[12:39:55.938999] sendHELO:132 [0x655708] cap: Model=squeezelite,ModelName=SqueezeLite,AccuratePlayPoints=0,HasDigitalOut=0,MaxSampleRate=96000,pcm,aif,flc,aac,mp3
[12:39:55.991584] process:562 [0x655708] strm
[12:39:55.991677] process_strm:241 [0x655708] strm command q
[12:39:55.991691] decode_flush:197 [0x655708]: decode flush
[12:39:55.991702] output_flush:858 [0x655708]: flush output buffer
[12:39:55.991828] sq_callback:247 [0x6b2ba0]: device off or not controlled by LMS
[12:39:55.992423] process:562 [0x655708] strm
[12:39:55.992454] process_strm:241 [0x655708] strm command q
[12:39:55.992466] decode_flush:197 [0x655708]: decode flush
[12:39:55.992477] output_flush:858 [0x655708]: flush output buffer
[12:39:55.992494] sq_callback:247 [0x6b2ba0]: device off or not controlled by LMS
[12:39:55.993475] process:562 [0x655708] setd
[12:39:55.993504] sendSETDName:226 set playername: Living room
[12:39:55.994082] process:562 [0x655708] setd
[12:39:55.994540] process:562 [0x655708] aude
[12:39:55.994571] process_aude:446 [0x655708] on/off using aude 1
[12:39:55.994584] sq_callback:243 [0x6b2ba0]: device set on/off 1
[12:39:55.994943] process:562 [0x655708] audg
[12:39:55.994969] process_audg:473 [0x655708] (old) audg gainL: 128 gainR: 128
[12:39:58.001369] process:562 [0x655708] strm
[12:39:58.001484] process_strm:241 [0x655708] strm command t
[12:39:58.001508] sendSTAT:167 [0x655708] STAT: STMt
[12:39:58.002976] process:562 [0x652720] strm
[12:39:58.003218] process_strm:241 [0x652720] strm command t
[12:39:58.003406] sendSTAT:167 [0x652720] STAT: STMt
[12:39:58.861107] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:39:58.992861] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:01.906861] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:02.000690] process:562 [0x655708] strm
[12:40:02.000758] process_strm:241 [0x655708] strm command t
[12:40:02.000767] sendSTAT:167 [0x655708] STAT: STMt
[12:40:02.001238] process:562 [0x652720] strm
[12:40:02.001254] process_strm:241 [0x652720] strm command t
[12:40:02.001313] sendSTAT:167 [0x652720] STAT: STMt
[12:40:02.076521] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:04.948887] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:05.076922] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:06.001978] process:562 [0x655708] strm
[12:40:06.002094] process_strm:241 [0x655708] strm command t
[12:40:06.002117] sendSTAT:167 [0x655708] STAT: STMt
[12:40:06.003852] process:562 [0x652720] strm
[12:40:06.003901] process_strm:241 [0x652720] strm command t
[12:40:06.003921] sendSTAT:167 [0x652720] STAT: STMt
[12:40:07.954178] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:08.126549] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:10.002833] process:562 [0x655708] strm
[12:40:10.002950] process_strm:241 [0x655708] strm command t
[12:40:10.002974] sendSTAT:167 [0x655708] STAT: STMt
[12:40:10.005435] process:562 [0x652720] strm
[12:40:10.005510] process_strm:241 [0x652720] strm command t
[12:40:10.005533] sendSTAT:167 [0x652720] STAT: STMt
[12:40:10.638684] UpdateMRThread:628 Begin Cast devices update
[12:40:11.004610] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:11.179116] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:13.492672] process:562 [0x652720] strm
[12:40:13.492801] process_strm:241 [0x652720] strm command q
[12:40:13.492822] decode_flush:197 [0x652720]: decode flush
[12:40:13.492841] output_flush:858 [0x652720]: flush output buffer
[12:40:13.492879] CastStop:203 [0x6b2440]: Stop req w/o session or connect
[12:40:13.698161] process:562 [0x652720] audg
[12:40:13.698280] process_audg:473 [0x652720] (old) audg gainL: 46 gainR: 46
[12:40:13.703943] process:562 [0x652720] strm
[12:40:13.704056] process_strm:238 [0x652720] strm command s
[12:40:13.704077] process_strm:309 [0x652720], strm s autostart: 1 transition period: 10 transition type: 0 codec: m
[12:40:13.704099] sendSTAT:165 [0x652720]: STAT:[STMf] msplayed 0
[12:40:13.704118] sendSTAT:167 [0x652720] STAT: STMf
[12:40:13.704175] codec_open:226 codec open: 'm'
[12:40:13.704231] stream_sock:392 [0x652720] connecting to 10.0.0.252:9000
[12:40:13.704412] stream_sock:421 [0x652720] header: GET /stream.mp3?player=1c:5a:6b:b9:89:e1 HTTP/1.0

[12:40:13.704528] sq_callback:262 [0x6b2440]: codec:m, ch:255, s:255, r:255
[12:40:13.833454] sq_get_metadata:583 [0x652720]: idx 0
    artist:a-ha
    album:Hunting High and Low
    title:Love Is Reason
    genre:Alternative
    duration:187.223
    size:0
    cover:http://10.0.0.252:9000/music/d5be518f/cover.jpg
[12:40:13.834113] SendCastMessage:265 [0x87e660]: Cast sending: {"type":"LAUNCH","requestId":1,"appId":"CC1AD845"}
[12:40:13.834271] CastLoad:142 [0x6b2440]: Queuing LOAD
[12:40:13.834299] sq_callback:305 [0x6b2440]: current URI set http://10.0.0.252:49152/LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3
[12:40:13.834479] sendSTAT:165 [0x652720]: STAT:[STMc] msplayed 0
[12:40:13.834508] sendSTAT:167 [0x652720] STAT: STMc
[12:40:13.834574] process:562 [0x652720] audg
[12:40:13.834598] process_audg:473 [0x652720] (old) audg gainL: 46 gainR: 46
[12:40:13.847751] stream_thread:181 [0x652720] headers: len: 116
HTTP/1.1 200 OK
Server: Logitech Media Server (7.9.0 - 1454098279)
Connection: close
Content-Type: audio/mpeg

[12:40:13.848026] sendRESP:196 RESP
[12:40:13.905061] SendCastMessage:265 [0x87e660]: Cast sending: {"type":"SET_VOLUME","requestId":2,"volume":{"level":0.500000,"muted":false}}
[12:40:13.905126] CastSimple:177 [0x6b2440]: Queuing PLAY
[12:40:13.915738] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[12:40:14.176457] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:14.303994] process:562 [0x655708] strm
[12:40:14.304069] process_strm:241 [0x655708] strm command t
[12:40:14.304081] sendSTAT:167 [0x655708] STAT: STMt
[12:40:14.304654] process:562 [0x652720] strm
[12:40:14.304674] process_strm:241 [0x652720] strm command t
[12:40:14.304684] sendSTAT:167 [0x652720] STAT: STMt
[12:40:14.582604] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:14.829895] stream_thread:255 [0x652720] end of stream (t:3744476)
[12:40:14.830151] sendDSCO:183 DSCO: 0
[12:40:14.831737] process:562 [0x652720] strm
[12:40:14.831888] process_strm:238 [0x652720] strm command u
[12:40:14.831912] process_strm:285 [0x652720] unpause at: 0 now: 2656587421
[12:40:14.831933] sendSTAT:165 [0x652720]: STAT:[STMr] msplayed 0
[12:40:14.831951] sendSTAT:167 [0x652720] STAT: STMr
[12:40:14.869393] output_thru_thread:761 [0x652720] wrote total 3744476
[12:40:14.987026] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:2)
[12:40:16.360062] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:1)
[12:40:16.360174] CastSocketThread:667 [0x6b2440]: Receiver launched
[12:40:16.360307] SendCastMessage:265 [0x87e660]: Cast sending: {"type":"CONNECT","origin":{}}
[12:40:16.360537] SendCastMessage:265 [0x87e660]: Cast sending: {
 "autoplay": false,
 "currentTime": 0.0,
 "requestId": 3,
 "type": "LOAD",
 "sessionId": "CBE8B602-8AF8-46B2-86E1-5E8720A5657D",
 "media": {
  "contentId": "http://10.0.0.252:49152/LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3",
  "streamType": "BUFFERED",
  "metadata": {
   "images": [
    {
     "url": "http://10.0.0.252:9000/music/d5be518f/cover.jpg"
    }
   ],
   "trackNumber": 8,
   "title": "Love Is Reason",
   "metadataType": 3,
   "artist": "a-ha",
   "albumName": "Hunting High and Low",
   "albumArtist": "a-ha"
  },
  "contentType": "audio/mpeg"
 }
}
[12:40:16.896177] WebGetInfo:40 Headers: Connection: keep-alive
[12:40:16.896295] WebGetInfo:40 Headers: CAST-DEVICE-CAPABILITIES: {"bluetooth_supported":false,"display_supported":true}
[12:40:16.896326] sq_get_info:677 [0x652720]: GetInfo /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3 -2 audio/mpeg
[12:40:16.896347] WebGetInfo:63 [0x652720]: GetInfo /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3 -2 audio/mpeg
[12:40:17.025301] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:17.025597] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:17.227016] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:17.861470] CastSocketThread:628 [0x6b2440]: type:LOAD_FAILED (id:3)
[12:40:17.861592] ProcessQueue:519 [0x6b2440]: PLAY un-queued but no media session
[12:40:19.002161] process:562 [0x655708] strm
[12:40:19.002282] process_strm:241 [0x655708] strm command t
[12:40:19.002306] sendSTAT:167 [0x655708] STAT: STMt
[12:40:19.010660] process:562 [0x652720] strm
[12:40:19.010783] process_strm:241 [0x652720] strm command t
[12:40:19.010807] sendSTAT:167 [0x652720] STAT: STMt
[12:40:20.060080] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:20.062151] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:20.236630] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:23.003459] process:562 [0x655708] strm
[12:40:23.003536] process_strm:241 [0x655708] strm command t
[12:40:23.003548] sendSTAT:167 [0x655708] STAT: STMt
[12:40:23.004512] process:562 [0x652720] strm
[12:40:23.004543] process_strm:241 [0x652720] strm command t
[12:40:23.004553] sendSTAT:167 [0x652720] STAT: STMt
[12:40:23.105830] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:23.105940] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:23.236684] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:26.076946] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[12:40:26.078346] UpdateMRThread:712 End Cast devices update 15440
[12:40:26.155759] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:26.155930] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:26.286391] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:27.002701] process:562 [0x655708] strm
[12:40:27.002815] process_strm:241 [0x655708] strm command t
[12:40:27.002840] sendSTAT:167 [0x655708] STAT: STMt
[12:40:27.004426] process:562 [0x652720] strm
[12:40:27.004474] process_strm:241 [0x652720] strm command t
[12:40:27.004496] sendSTAT:167 [0x652720] STAT: STMt
[12:40:29.161182] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:29.161362] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:29.326347] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:31.001341] process:562 [0x655708] strm
[12:40:31.001460] process_strm:241 [0x655708] strm command t
[12:40:31.001486] sendSTAT:167 [0x655708] STAT: STMt
[12:40:31.002977] process:562 [0x652720] strm
[12:40:31.003024] process_strm:241 [0x652720] strm command t
[12:40:31.003046] sendSTAT:167 [0x652720] STAT: STMt
[12:40:32.209569] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:32.209746] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:32.379683] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:35.001097] process:562 [0x655708] strm
[12:40:35.001301] process_strm:241 [0x655708] strm command t
[12:40:35.001341] sendSTAT:167 [0x655708] STAT: STMt
[12:40:35.013235] process:562 [0x652720] strm
[12:40:35.013362] process_strm:241 [0x652720] strm command t
[12:40:35.013387] sendSTAT:167 [0x652720] STAT: STMt
[12:40:35.216662] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:35.216790] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:35.425807] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:38.216766] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:38.216944] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:38.475551] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:39.002023] process:562 [0x655708] strm
[12:40:39.002141] process_strm:241 [0x655708] strm command t
[12:40:39.002166] sendSTAT:167 [0x655708] STAT: STMt
[12:40:39.003995] process:562 [0x652720] strm
[12:40:39.004048] process_strm:241 [0x652720] strm command t
[12:40:39.004071] sendSTAT:167 [0x652720] STAT: STMt
[12:40:40.664125] UpdateMRThread:628 Begin Cast devices update
[12:40:41.269933] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:41.270113] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[12:40:41.475200] CastSocketThread:628 [0x6b2ba0]: type:PONG (id:0)
[12:40:43.002226] process:562 [0x655708] strm
[12:40:43.002612] process_strm:241 [0x655708] strm command t
[12:40:43.002648] sendSTAT:167 [0x655708] STAT: STMt
[12:40:43.003836] process:562 [0x652720] strm
[12:40:43.003881] process_strm:241 [0x652720] strm command t
[12:40:43.003934] sendSTAT:167 [0x652720] STAT: STMt
philippe44 commented 8 years ago

I think the problem really comes from the range request that the AndroidTV sends. I use libupnp as my webserver and use chuncked-encoding to send files over HTTP to the CC device as I don't know in advance the file size. Problem is that when libupnp receives a request with a range and is set to use chuncked-encoding, it will respond with a non satisfiable range (HTTP 416) and this makes AndroidTV fails (the LOAD request fails). I'm not the best expert there and there is a lot of litterature wrt handling such cases, but I think in that case the AndroidTV should not simply fail because of the HTTP 416, although I'm sure some would argue that range 0-1 should always be satisfied is there is "anything" to send ... anyway, that would require me to patch again libupnp for the 0-1 range request and this is painful (I already did a lot for open-range request/reponse). But there is a not so elegant workaround that might work. There is a parameter (hidden) in the castbridge.xml config file that is named . It sets the type of transfer-encoding that libupnp use and how it responds to open-range : -3 = chuncked with HTTP 206 response to range 0-, -2 = chuncked with HTTP 200 reponse to range 0- (this is the default for castbridge). There are a few other negative value that have no interest here (except -5, but let's try first with something else), but if you set this to large positive value, then castbridge will pretend that the file to be sent is that length and will close the connection when the real length is reached. I don't know if it works for AndroidTV, but I had to do that for my UPnP bridge where the variation of players reaction is so diverse ... (for example, this is how Sonos work best)

[edit]: Well, I've tried to do a libupnp modification, in 0.2.0.2-dev-1. Can you tell me if it works and if not, can you send me the same trace + tcpdump you did at the beginning ?

philippe44 commented 8 years ago

any update ? I'm trying to see if this touchy modification of libupnp works

gdhgdhgdh commented 8 years ago

Ah I didn't see the edit that you'd pushed an update :) Let's give it a go. (I needed to chmod a+x the contents of the Bin/ directory)

The short version is that is still doesn't work, but the failure mode is more interesting this time.

I can see HTTP requests back and forth including the actual audio/mpeg data, and the TV displays metadata and album art just like last time, but there's no actual audio being played, and just the blue 'progress bar' whizzing forever rather than showing a fixed number of minutes and seconds.


Starting Squeeze2cast: /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/CastBridge/Bin/squeeze2cast-x86-64 -Z -I -f /var/log/squeezeboxserver/castbridge.log -d all=debug -x /var/lib/squeezeboxserver/prefs/castbridge.xml
[21:23:14.012247] main:1175 Starting squeeze2cast version: v0.2.0.2-dev-1 (Mar  5 2016 @ 17:36:46)

[21:23:14.012392] decode_init:125 init decode, include codecs:  exclude codecs: 
[21:23:14.012416] main:1206 Buffer path /tmp
[21:23:14.027415] Initialize:807 UPnP init success - 10.0.0.252:49152
[21:23:14.027473] Initialize:831 WebServer enabled
[21:23:14.027486] Initialize:842 VirtualDir set for Squeezelite
[21:23:14.027495] Initialize:859 Callbacks registered for VirtualDir
[21:23:14.035307] UpdateMRThread:628 Begin Cast devices update
[21:23:29.067997] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[21:23:29.068885] UpdateMRThread:712 End Cast devices update 15033
[21:23:44.060880] UpdateMRThread:628 Begin Cast devices update
[21:23:59.470976] AddCastDevice:912 [0x6b2440]: adding renderer (Office TV)
[21:23:59.564333] CastConnect:380 [0x6b2440]: SSL connection opened [0x2340c70]
[21:23:59.564604] SendCastMessage:265 [0x2340c70]: Cast sending: {"type":"CONNECT"}
[21:23:59.564878] stream_thread_init:296 [0x652720] streambuf size: 2457600
[21:23:59.572473] output_mr_thread_init:780 [0x652720] init output media renderer
[21:23:59.572639] decode_thread_init:152 [0x652720]: init decode
[21:23:59.572750] discover_server:814 [0x652720] sending discovery
[21:23:59.573654] discover_server:843 [0x652720] got response from: 10.0.0.252:3483
[21:23:59.573723] slimproto_thread_init:1007 [0x652720] connecting to 10.0.0.252:3483
[21:23:59.573840] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[21:23:59.574544] UpdateMRThread:712 End Cast devices update 15514
[21:23:59.576378] slimproto:885 [0x652720] connected
[21:23:59.576474] sendHELO:131 [0x652720] mac: 1c:5a:6b:b9:89:e1
[21:23:59.576498] sendHELO:132 [0x652720] cap: Model=squeezelite,ModelName=SqueezeLite,AccuratePlayPoints=0,HasDigitalOut=0,MaxSampleRate=48000,pcm,aif,aac,flc,mp3
[21:23:59.656114] process:562 [0x652720] strm
[21:23:59.656231] process_strm:241 [0x652720] strm command q
[21:23:59.656295] decode_flush:197 [0x652720]: decode flush
[21:23:59.656363] output_flush:858 [0x652720]: flush output buffer
[21:23:59.656425] sq_callback:247 [0x6b2440]: device off or not controlled by LMS
[21:23:59.657568] process:562 [0x652720] strm
[21:23:59.657618] process_strm:241 [0x652720] strm command q
[21:23:59.657637] decode_flush:197 [0x652720]: decode flush
[21:23:59.657656] output_flush:858 [0x652720]: flush output buffer
[21:23:59.657686] sq_callback:247 [0x6b2440]: device off or not controlled by LMS
[21:23:59.659383] process:562 [0x652720] setd
[21:23:59.659437] sendSETDName:226 set playername: Office TV
[21:23:59.660423] process:562 [0x652720] setd
[21:23:59.660818] process:562 [0x652720] aude
[21:23:59.660866] process_aude:446 [0x652720] on/off using aude 1
[21:23:59.660887] sq_callback:243 [0x6b2440]: device set on/off 1
[21:23:59.661622] process:562 [0x652720] audg
[21:23:59.661674] process_audg:473 [0x652720] (old) audg gainL: 43 gainR: 43
[21:24:02.574302] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:03.002990] process:562 [0x652720] strm
[21:24:03.003107] process_strm:241 [0x652720] strm command t
[21:24:03.003133] sendSTAT:167 [0x652720] STAT: STMt
[21:24:05.661693] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:08.002506] process:562 [0x652720] strm
[21:24:08.002622] process_strm:241 [0x652720] strm command t
[21:24:08.002647] sendSTAT:167 [0x652720] STAT: STMt
[21:24:08.705127] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:11.754872] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:12.003350] process:562 [0x652720] strm
[21:24:12.003501] process_strm:241 [0x652720] strm command t
[21:24:12.003625] sendSTAT:167 [0x652720] STAT: STMt
[21:24:14.079957] UpdateMRThread:628 Begin Cast devices update
[21:24:14.801044] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:17.003228] process:562 [0x652720] strm
[21:24:17.003570] process_strm:241 [0x652720] strm command t
[21:24:17.003606] sendSTAT:167 [0x652720] STAT: STMt
[21:24:17.800060] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:20.805729] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:21.003215] process:562 [0x652720] strm
[21:24:21.003507] process_strm:241 [0x652720] strm command t
[21:24:21.003540] sendSTAT:167 [0x652720] STAT: STMt
[21:24:23.849796] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:26.003470] process:562 [0x652720] strm
[21:24:26.003587] process_strm:241 [0x652720] strm command t
[21:24:26.003612] sendSTAT:167 [0x652720] STAT: STMt
[21:24:26.900397] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:29.113870] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[21:24:29.114288] UpdateMRThread:712 End Cast devices update 15035
[21:24:29.945380] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:31.004570] process:562 [0x652720] strm
[21:24:31.004689] process_strm:241 [0x652720] strm command t
[21:24:31.004715] sendSTAT:167 [0x652720] STAT: STMt
[21:24:32.995681] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:36.001370] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:36.003863] process:562 [0x652720] strm
[21:24:36.003935] process_strm:241 [0x652720] strm command t
[21:24:36.003959] sendSTAT:167 [0x652720] STAT: STMt
[21:24:39.049654] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:40.004061] process:562 [0x652720] strm
[21:24:40.004181] process_strm:241 [0x652720] strm command t
[21:24:40.004206] sendSTAT:167 [0x652720] STAT: STMt
[21:24:42.050953] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:44.003251] process:562 [0x652720] strm
[21:24:44.003537] process_strm:241 [0x652720] strm command t
[21:24:44.003570] sendSTAT:167 [0x652720] STAT: STMt
[21:24:44.104133] UpdateMRThread:628 Begin Cast devices update
[21:24:45.101858] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:48.155408] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:49.003350] process:562 [0x652720] strm
[21:24:49.003466] process_strm:241 [0x652720] strm command t
[21:24:49.003492] sendSTAT:167 [0x652720] STAT: STMt
[21:24:51.196888] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:54.002709] process:562 [0x652720] strm
[21:24:54.002833] process_strm:241 [0x652720] strm command t
[21:24:54.002858] sendSTAT:167 [0x652720] STAT: STMt
[21:24:54.245322] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:57.295196] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:24:58.002356] process:562 [0x652720] strm
[21:24:58.002606] process_strm:241 [0x652720] strm command t
[21:24:58.002637] sendSTAT:167 [0x652720] STAT: STMt
[21:24:59.470064] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[21:24:59.471522] UpdateMRThread:712 End Cast devices update 15367
[21:25:00.300693] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:02.004205] process:562 [0x652720] strm
[21:25:02.004320] process_strm:241 [0x652720] strm command t
[21:25:02.004345] sendSTAT:167 [0x652720] STAT: STMt
[21:25:03.345567] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:06.350264] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:07.002097] process:562 [0x652720] strm
[21:25:07.002274] process_strm:241 [0x652720] strm command t
[21:25:07.002341] sendSTAT:167 [0x652720] STAT: STMt
[21:25:09.352341] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:12.002749] process:562 [0x652720] strm
[21:25:12.002839] process_strm:241 [0x652720] strm command t
[21:25:12.002856] sendSTAT:167 [0x652720] STAT: STMt
[21:25:12.401521] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:14.126149] UpdateMRThread:628 Begin Cast devices update
[21:25:15.445808] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:16.419904] process:562 [0x652720] strm
[21:25:16.420021] process_strm:241 [0x652720] strm command q
[21:25:16.420043] decode_flush:197 [0x652720]: decode flush
[21:25:16.420096] output_flush:858 [0x652720]: flush output buffer
[21:25:16.420135] CastStop:203 [0x6b2440]: Stop req w/o session or connect
[21:25:16.507751] process:562 [0x652720] audg
[21:25:16.507865] process_audg:473 [0x652720] (old) audg gainL: 43 gainR: 43
[21:25:16.510720] process:562 [0x652720] strm
[21:25:16.510803] process_strm:238 [0x652720] strm command s
[21:25:16.510824] process_strm:309 [0x652720], strm s autostart: 1 transition period: 10 transition type: 0 codec: m
[21:25:16.510846] sendSTAT:165 [0x652720]: STAT:[STMf] msplayed 0
[21:25:16.510864] sendSTAT:167 [0x652720] STAT: STMf
[21:25:16.510921] codec_open:226 codec open: 'm'
[21:25:16.510975] stream_sock:392 [0x652720] connecting to 10.0.0.252:9000
[21:25:16.511136] stream_sock:421 [0x652720] header: GET /stream.mp3?player=1c:5a:6b:b9:89:e1 HTTP/1.0

[21:25:16.511279] sq_callback:262 [0x6b2440]: codec:m, ch:255, s:255, r:255
[21:25:16.597941] sq_get_metadata:583 [0x652720]: idx 0
    artist:a-ha
    album:Hunting High and Low
    title:Love Is Reason
    genre:Alternative
    duration:187.223
    size:0
    cover:http://10.0.0.252:9000/music/d5be518f/cover.jpg
[21:25:16.598311] SendCastMessage:265 [0x2340c70]: Cast sending: {"type":"LAUNCH","requestId":1,"appId":"CC1AD845"}
[21:25:16.598410] CastLoad:142 [0x6b2440]: Queuing LOAD
[21:25:16.598433] sq_callback:305 [0x6b2440]: current URI set http://10.0.0.252:49152/LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3
[21:25:16.598476] sendSTAT:165 [0x652720]: STAT:[STMc] msplayed 0
[21:25:16.598496] sendSTAT:167 [0x652720] STAT: STMc
[21:25:16.598781] process:562 [0x652720] audg
[21:25:16.598810] process_audg:473 [0x652720] (old) audg gainL: 43 gainR: 43
[21:25:16.605232] stream_thread:181 [0x652720] headers: len: 116
HTTP/1.1 200 OK
Server: Logitech Media Server (7.9.0 - 1454098279)
Connection: close
Content-Type: audio/mpeg

[21:25:16.605405] sendRESP:196 RESP
[21:25:16.625809] SendCastMessage:265 [0x2340c70]: Cast sending: {"type":"SET_VOLUME","requestId":2,"volume":{"level":0.480000,"muted":false}}
[21:25:16.625880] CastSimple:177 [0x6b2440]: Queuing PLAY
[21:25:16.806145] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:25:17.004527] process:562 [0x652720] strm
[21:25:17.004700] process_strm:241 [0x652720] strm command t
[21:25:17.004726] sendSTAT:167 [0x652720] STAT: STMt
[21:25:17.194250] stream_thread:255 [0x652720] end of stream (t:3744476)
[21:25:17.194476] sendDSCO:183 DSCO: 0
[21:25:17.195934] process:562 [0x652720] strm
[21:25:17.196000] process_strm:238 [0x652720] strm command u
[21:25:17.196021] process_strm:285 [0x652720] unpause at: 0 now: 3465689785
[21:25:17.196041] sendSTAT:165 [0x652720]: STAT:[STMr] msplayed 0
[21:25:17.196060] sendSTAT:167 [0x652720] STAT: STMr
[21:25:17.243311] output_thru_thread:761 [0x652720] wrote total 3744476
[21:25:17.853190] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:2)
[21:25:18.412182] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:21.496046] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:22.003048] process:562 [0x652720] strm
[21:25:22.003165] process_strm:241 [0x652720] strm command t
[21:25:22.003189] sendSTAT:167 [0x652720] STAT: STMt
[21:25:22.618221] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:1)
[21:25:22.618347] CastSocketThread:667 [0x6b2440]: Receiver launched
[21:25:22.618618] SendCastMessage:265 [0x2340c70]: Cast sending: {"type":"CONNECT","origin":{}}
[21:25:22.618826] SendCastMessage:265 [0x2340c70]: Cast sending: {
 "sessionId": "6D03715D-4708-4225-9286-2534AB89E0A9",
 "type": "LOAD",
 "requestId": 3,
 "currentTime": 0.0,
 "autoplay": false,
 "media": {
  "contentId": "http://10.0.0.252:49152/LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3",
  "metadata": {
   "metadataType": 3,
   "albumName": "Hunting High and Low",
   "title": "Love Is Reason",
   "albumArtist": "a-ha",
   "trackNumber": 8,
   "artist": "a-ha",
   "images": [
    {
     "url": "http://10.0.0.252:9000/music/d5be518f/cover.jpg"
    }
   ]
  },
  "streamType": "BUFFERED",
  "contentType": "audio/mpeg"
 }
}
[21:25:22.933992] WebGetInfo:40 Headers: Connection: keep-alive
[21:25:22.934074] WebGetInfo:40 Headers: CAST-DEVICE-CAPABILITIES: {"bluetooth_supported":false,"display_supported":true}
[21:25:22.934090] sq_get_info:677 [0x652720]: GetInfo /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3 -2 audio/mpeg
[21:25:22.934101] WebGetInfo:63 [0x652720]: GetInfo /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3 -2 audio/mpeg
[21:25:22.934234] sq_open:743 [0x652720]: open
[21:25:22.934248] WebOpen:77 Webserver Open /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3
[21:25:22.934258] sq_seek:860 [0x652720]: seek 0 (c:36984464)
[21:25:22.934281] WebSeek:107 [0x653140]: seek 0, 1 (rc:0)
[21:25:22.934310] sq_read:934 [0x652720]: read 1 (a:1 r:1 w:100)
[21:25:22.934321] WebRead:94 read 1 on 1
[21:25:22.934400] sq_close:829 [0x652720]: read total:1
[21:25:22.934618] WebClose:118 webserver close
[21:25:23.251962] WebGetInfo:40 Headers: Connection: Keep-Alive
[21:25:23.252051] sq_get_info:677 [0x652720]: GetInfo /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3 -2 audio/mpeg
[21:25:23.252065] WebGetInfo:63 [0x652720]: GetInfo /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3 -2 audio/mpeg
[21:25:23.252245] sq_open:743 [0x652720]: open
[21:25:23.252263] WebOpen:77 Webserver Open /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3
[21:25:23.255011] sq_read:934 [0x652720]: read 1048576 (a:1048576 r:1048576 w:100)
[21:25:23.255100] WebRead:94 read 1048576 on 1048576
[21:25:23.440787] sq_read:934 [0x652720]: read 1048576 (a:1048576 r:1048576 w:100)
[21:25:23.440881] WebRead:94 read 1048576 on 1048576
[21:25:23.859356] sq_read:934 [0x652720]: read 1048576 (a:1048576 r:1048576 w:100)
[21:25:23.859470] WebRead:94 read 1048576 on 1048576
[21:25:23.921250] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:25:23.939574] CastSocketThread:625 [0x6b2440]: type:MEDIA_STATUS (id:3) IDLE
[21:25:23.939640] CastSocketThread:682 [0x6b2440]: Media session id 1
[21:25:23.939706] SendCastMessage:265 [0x2340c70]: Cast sending: {"type":"SET_VOLUME","requestId":4,"mediaSessionId":1,"volume":{"level":0.500000,"muted":false}}
[21:25:23.939731] SendCastMessage:265 [0x2340c70]: Cast sending: {"type":"PLAY","requestId":5,"mediaSessionId":1}
[21:25:23.980660] CastSocketThread:628 [0x6b2440]: type:INVALID_REQUEST (id:4)
[21:25:23.994233] CastSocketThread:628 [0x6b2440]: type:INVALID_REQUEST (id:5)
[21:25:24.470582] sq_read:934 [0x652720]: read 1048576 (a:1048576 r:598748 w:100)
[21:25:24.470653] WebRead:94 read 598748 on 1048576
[21:25:24.614607] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:24.614813] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:24.864314] sq_read:934 [0x652720]: read 1048576 (a:1048576 r:0 w:100)
[21:25:24.864401] sq_read:975 [0x652720]: read (end of track) w:100
[21:25:24.864410] WebRead:94 read 0 on 1048576
[21:25:24.864542] sq_close:829 [0x652720]: read total:3744476
[21:25:24.864553] WebClose:118 webserver close
[21:25:26.002639] process:562 [0x652720] strm
[21:25:26.002750] process_strm:241 [0x652720] strm command t
[21:25:26.002810] sendSTAT:167 [0x652720] STAT: STMt
[21:25:27.510300] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:27.510477] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:29.431497] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[21:25:29.432429] UpdateMRThread:712 End Cast devices update 15306
[21:25:30.596637] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:30.596932] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:31.004337] process:562 [0x652720] strm
[21:25:31.004804] process_strm:241 [0x652720] strm command t
[21:25:31.004836] sendSTAT:167 [0x652720] STAT: STMt
[21:25:33.602730] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:33.608761] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:35.003195] process:562 [0x652720] strm
[21:25:35.003310] process_strm:241 [0x652720] strm command t
[21:25:35.003334] sendSTAT:167 [0x652720] STAT: STMt
[21:25:36.603956] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:36.604247] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:39.650781] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:39.651118] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:40.004534] process:562 [0x652720] strm
[21:25:40.004735] process_strm:241 [0x652720] strm command t
[21:25:40.004766] sendSTAT:167 [0x652720] STAT: STMt
[21:25:42.655965] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:42.656242] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:44.041071] process:562 [0x652720] strm
[21:25:44.041159] process_strm:241 [0x652720] strm command t
[21:25:44.041175] sendSTAT:167 [0x652720] STAT: STMt
[21:25:44.148271] UpdateMRThread:628 Begin Cast devices update
[21:25:45.652652] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:45.653446] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:48.702590] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:48.702874] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:49.003391] process:562 [0x652720] strm
[21:25:49.003507] process_strm:241 [0x652720] strm command t
[21:25:49.003532] sendSTAT:167 [0x652720] STAT: STMt
[21:25:51.752182] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:51.752527] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:54.003416] process:562 [0x652720] strm
[21:25:54.003530] process_strm:241 [0x652720] strm command t
[21:25:54.003553] sendSTAT:167 [0x652720] STAT: STMt
[21:25:54.747887] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:54.748191] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:57.753697] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:57.754190] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:25:59.003615] process:562 [0x652720] strm
[21:25:59.003729] process_strm:241 [0x652720] strm command t
[21:25:59.003753] sendSTAT:167 [0x652720] STAT: STMt
[21:25:59.471841] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[21:25:59.472677] UpdateMRThread:712 End Cast devices update 15324
[21:26:00.757810] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:00.758027] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:03.802264] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:03.802562] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:04.004331] process:562 [0x652720] strm
[21:26:04.004443] process_strm:241 [0x652720] strm command t
[21:26:04.004466] sendSTAT:167 [0x652720] STAT: STMt
[21:26:06.852064] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:06.854483] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:09.005233] process:562 [0x652720] strm
[21:26:09.005363] process_strm:241 [0x652720] strm command t
[21:26:09.005390] sendSTAT:167 [0x652720] STAT: STMt
[21:26:09.863574] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:09.863865] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:12.864024] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:12.864209] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:13.002843] process:562 [0x652720] strm
[21:26:13.002958] process_strm:241 [0x652720] strm command t
[21:26:13.003193] sendSTAT:167 [0x652720] STAT: STMt
[21:26:14.171446] UpdateMRThread:628 Begin Cast devices update
[21:26:15.916492] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:15.916783] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:17.003213] process:562 [0x652720] strm
[21:26:17.003298] process_strm:241 [0x652720] strm command t
[21:26:17.003314] sendSTAT:167 [0x652720] STAT: STMt
[21:26:18.918362] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:18.918654] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:21.966544] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:21.967138] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:22.002021] process:562 [0x652720] strm
[21:26:22.002187] process_strm:241 [0x652720] strm command t
[21:26:22.002263] sendSTAT:167 [0x652720] STAT: STMt
[21:26:24.967106] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:24.967420] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:27.002554] process:562 [0x652720] strm
[21:26:27.002709] process_strm:241 [0x652720] strm command t
[21:26:27.002735] sendSTAT:167 [0x652720] STAT: STMt
[21:26:27.973500] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:27.973659] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:29.203313] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[21:26:29.203817] UpdateMRThread:712 End Cast devices update 15031
[21:26:30.983866] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:30.984059] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:32.002475] process:562 [0x652720] strm
[21:26:32.002587] process_strm:241 [0x652720] strm command t
[21:26:32.002611] sendSTAT:167 [0x652720] STAT: STMt
[21:26:33.977093] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:33.977498] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:36.003341] process:562 [0x652720] strm
[21:26:36.003489] process_strm:241 [0x652720] strm command t
[21:26:36.003516] sendSTAT:167 [0x652720] STAT: STMt
[21:26:37.026772] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:37.027058] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:40.071135] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:40.071408] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:41.002740] process:562 [0x652720] strm
[21:26:41.002836] process_strm:241 [0x652720] strm command t
[21:26:41.002852] sendSTAT:167 [0x652720] STAT: STMt
[21:26:43.073483] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:43.073836] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:44.195366] UpdateMRThread:628 Begin Cast devices update
[21:26:45.003213] process:562 [0x652720] strm
[21:26:45.003439] process_strm:241 [0x652720] strm command t
[21:26:45.003466] sendSTAT:167 [0x652720] STAT: STMt
[21:26:46.123476] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:46.123787] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:49.004644] process:562 [0x652720] strm
[21:26:49.004807] process_strm:241 [0x652720] strm command t
[21:26:49.004840] sendSTAT:167 [0x652720] STAT: STMt
[21:26:49.123524] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:49.133318] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:52.169102] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:52.169435] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:53.002631] process:562 [0x652720] strm
[21:26:53.002746] process_strm:241 [0x652720] strm command t
[21:26:53.002771] sendSTAT:167 [0x652720] STAT: STMt
[21:26:55.169066] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:55.169338] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:58.011798] process:562 [0x652720] strm
[21:26:58.011923] process_strm:241 [0x652720] strm command t
[21:26:58.011949] sendSTAT:167 [0x652720] STAT: STMt
[21:26:58.223136] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:58.225511] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:26:59.473587] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[21:26:59.475000] UpdateMRThread:712 End Cast devices update 15279
[21:27:01.273796] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:01.274092] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:03.002314] process:562 [0x652720] strm
[21:27:03.002432] process_strm:241 [0x652720] strm command t
[21:27:03.002457] sendSTAT:167 [0x652720] STAT: STMt
[21:27:04.277779] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:04.278142] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:07.003322] process:562 [0x652720] strm
[21:27:07.003437] process_strm:241 [0x652720] strm command t
[21:27:07.003498] sendSTAT:167 [0x652720] STAT: STMt
[21:27:07.325340] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:07.325723] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:10.369948] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:10.370408] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:12.003146] process:562 [0x652720] strm
[21:27:12.003401] process_strm:241 [0x652720] strm command t
[21:27:12.003577] sendSTAT:167 [0x652720] STAT: STMt
[21:27:13.417981] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:13.418258] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:14.216651] UpdateMRThread:628 Begin Cast devices update
[21:27:16.004695] process:562 [0x652720] strm
[21:27:16.004822] process_strm:241 [0x652720] strm command t
[21:27:16.004848] sendSTAT:167 [0x652720] STAT: STMt
[21:27:16.414129] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:16.414302] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:19.469587] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:19.473087] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:21.003318] process:562 [0x652720] strm
[21:27:21.003440] process_strm:241 [0x652720] strm command t
[21:27:21.003465] sendSTAT:167 [0x652720] STAT: STMt
[21:27:22.512504] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:22.512809] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:25.003383] process:562 [0x652720] strm
[21:27:25.003522] process_strm:241 [0x652720] strm command t
[21:27:25.003550] sendSTAT:167 [0x652720] STAT: STMt
[21:27:25.517948] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:25.518240] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:28.517834] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:28.518138] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:29.248607] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[21:27:29.249661] UpdateMRThread:712 End Cast devices update 15033
[21:27:30.002090] process:562 [0x652720] strm
[21:27:30.002341] process_strm:241 [0x652720] strm command t
[21:27:30.002363] sendSTAT:167 [0x652720] STAT: STMt
[21:27:31.570584] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:31.570850] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:34.578105] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:34.578541] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:35.002253] process:562 [0x652720] strm
[21:27:35.002369] process_strm:241 [0x652720] strm command t
[21:27:35.002393] sendSTAT:167 [0x652720] STAT: STMt
[21:27:37.642214] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:37.642627] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:38.522051] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:38.522780] MRThread:552 [0x6b2440]: Volume local change 50
[21:27:38.528292] process:562 [0x652720] audg
[21:27:38.528369] process_audg:473 [0x652720] (old) audg gainL: 46 gainR: 46
[21:27:38.533574] SendCastMessage:265 [0x2340c70]: Cast sending: {"type":"SET_VOLUME","requestId":6,"volume":{"level":0.500000,"muted":false}}
[21:27:38.533729] process:562 [0x652720] audg
[21:27:38.533758] process_audg:473 [0x652720] (old) audg gainL: 46 gainR: 46
[21:27:38.533828] SendCastMessage:265 [0x2340c70]: Cast sending: {"type":"SET_VOLUME","requestId":7,"volume":{"level":0.500000,"muted":false}}
[21:27:39.003164] process:562 [0x652720] strm
[21:27:39.003284] process_strm:241 [0x652720] strm command t
[21:27:39.003309] sendSTAT:167 [0x652720] STAT: STMt
[21:27:39.449170] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:7)
[21:27:39.450334] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:6)
[21:27:39.530423] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:39.951999] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:40.261852] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:40.351549] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:40.404661] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:40.656402] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:40.656710] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:40.707517] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:41.102105] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:41.909186] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:42.034625] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:42.201462] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:42.475899] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:42.571929] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:43.252083] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:43.608876] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:43.609299] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:44.002773] process:562 [0x652720] strm
[21:27:44.002885] process_strm:241 [0x652720] strm command t
[21:27:44.002913] sendSTAT:167 [0x652720] STAT: STMt
[21:27:44.078035] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[21:27:44.079223] MRThread:552 [0x6b2440]: Volume local change 70
[21:27:44.084641] process:562 [0x652720] audg
[21:27:44.084708] process_audg:473 [0x652720] (old) audg gainL: 75 gainR: 75
[21:27:44.090837] SendCastMessage:265 [0x2340c70]: Cast sending: {"type":"SET_VOLUME","requestId":8,"volume":{"level":0.700000,"muted":false}}
[21:27:44.091027] process:562 [0x652720] audg
[21:27:44.091056] process_audg:473 [0x652720] (old) audg gainL: 75 gainR: 75
[21:27:44.091126] SendCastMessage:265 [0x2340c70]: Cast sending: {"type":"SET_VOLUME","requestId":9,"volume":{"level":0.700000,"muted":false}}
[21:27:44.240238] UpdateMRThread:628 Begin Cast devices update
[21:27:45.140320] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:8)
[21:27:45.150146] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:9)
[21:27:46.604251] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:46.605091] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:48.135507] process:562 [0x652720] strm
[21:27:48.135594] process_strm:241 [0x652720] strm command t
[21:27:48.135608] sendSTAT:167 [0x652720] STAT: STMt
[21:27:49.690122] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:49.690970] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:52.738412] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:52.740086] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:53.003310] process:562 [0x652720] strm
[21:27:53.003424] process_strm:241 [0x652720] strm command t
[21:27:53.003448] sendSTAT:167 [0x652720] STAT: STMt
[21:27:55.795160] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:55.796396] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:58.003612] process:562 [0x652720] strm
[21:27:58.003836] process_strm:241 [0x652720] strm command t
[21:27:58.003873] sendSTAT:167 [0x652720] STAT: STMt
[21:27:58.828454] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:58.828760] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:27:59.475444] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[21:27:59.478203] UpdateMRThread:712 End Cast devices update 15238
[21:28:01.836873] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:01.837343] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:03.002489] process:562 [0x652720] strm
[21:28:03.002610] process_strm:241 [0x652720] strm command t
[21:28:03.002635] sendSTAT:167 [0x652720] STAT: STMt
[21:28:04.833075] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:04.833243] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:07.887151] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:07.887508] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:08.003743] process:562 [0x652720] strm
[21:28:08.003998] process_strm:241 [0x652720] strm command t
[21:28:08.004033] sendSTAT:167 [0x652720] STAT: STMt
[21:28:10.886181] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:10.886493] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:13.003116] process:562 [0x652720] strm
[21:28:13.003235] process_strm:241 [0x652720] strm command t
[21:28:13.003260] sendSTAT:167 [0x652720] STAT: STMt
[21:28:13.935894] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:13.936191] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:14.260717] UpdateMRThread:628 Begin Cast devices update
[21:28:16.985964] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:16.986203] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:18.002673] process:562 [0x652720] strm
[21:28:18.002817] process_strm:241 [0x652720] strm command t
[21:28:18.002844] sendSTAT:167 [0x652720] STAT: STMt
[21:28:20.033519] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:20.033798] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:23.003860] process:562 [0x652720] strm
[21:28:23.004102] process_strm:241 [0x652720] strm command t
[21:28:23.004246] sendSTAT:167 [0x652720] STAT: STMt
[21:28:23.087322] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:23.087588] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:26.127134] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:26.127575] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:28.003936] process:562 [0x652720] strm
[21:28:28.004091] process_strm:241 [0x652720] strm command t
[21:28:28.004213] sendSTAT:167 [0x652720] STAT: STMt
[21:28:29.174257] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:29.174495] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:29.466751] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[21:28:29.468199] UpdateMRThread:712 End Cast devices update 15208
[21:28:32.001498] process:562 [0x652720] strm
[21:28:32.001578] process_strm:241 [0x652720] strm command t
[21:28:32.001591] sendSTAT:167 [0x652720] STAT: STMt
[21:28:32.230996] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:32.231231] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:35.237744] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:35.239664] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:37.050897] process:562 [0x652720] strm
[21:28:37.050997] process_strm:241 [0x652720] strm command t
[21:28:37.051016] sendSTAT:167 [0x652720] STAT: STMt
[21:28:38.277830] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:38.278070] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:41.287024] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:41.287564] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:42.006234] process:562 [0x652720] strm
[21:28:42.006487] process_strm:241 [0x652720] strm command t
[21:28:42.006510] sendSTAT:167 [0x652720] STAT: STMt
[21:28:44.283827] UpdateMRThread:628 Begin Cast devices update
[21:28:44.334547] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:44.334953] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:47.003081] process:562 [0x652720] strm
[21:28:47.003200] process_strm:241 [0x652720] strm command t
[21:28:47.003227] sendSTAT:167 [0x652720] STAT: STMt
[21:28:47.353126] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:47.353444] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:50.398248] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:50.398516] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:52.004347] process:562 [0x652720] strm
[21:28:52.004463] process_strm:241 [0x652720] strm command t
[21:28:52.004489] sendSTAT:167 [0x652720] STAT: STMt
[21:28:53.404965] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:53.405229] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:56.451541] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:56.452615] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:57.003964] process:562 [0x652720] strm
[21:28:57.004116] process_strm:241 [0x652720] strm command t
[21:28:57.004238] sendSTAT:167 [0x652720] STAT: STMt
[21:28:59.477906] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[21:28:59.478882] UpdateMRThread:712 End Cast devices update 15195
[21:28:59.498112] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:28:59.498404] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[21:29:01.003207] process:562 [0x652720] strm
[21:29:01.003379] process_strm:241 [0x652720] strm command t
[21:29:01.003406] sendSTAT:167 [0x652720] STAT: STMt
[21:29:02.243458] slimproto_close:942 [0x652720] slimproto stop for Office TV
[21:29:02.243580] output_mr_close:838 [0x652720] close media renderer
[21:29:02.318700] decode_close:180 close decode
[21:29:02.318836] stream_close:330 [0x652720] close stream
[21:29:02.393456] Stop:981 flush renderers ...
[21:29:02.393913] SendCastMessage:265 [0x2340c70]: Cast sending: {"type":"STOP","requestId":10,"mediaSessionId":1}
[21:29:02.503142] CastSocketThread:628 [0x6b2440]: type:INVALID_REQUEST (id:10)
[21:29:02.604773] read_bytes:169 [s-0x2340c70]: socket closed
[21:29:02.604904] CastSocketThread:605 [0x2348db0]: SSL connection closed
[21:29:02.605040] StopCastDevice:486 [0x6b2440]: Cast device stopped
[21:29:02.606051] Stop:987 terminate main thread ...
[21:29:02.606098] Stop:990 terminate libupnp ...
[21:29:02.606116] Terminate:869 un-register libupnp callbacks ...
[21:29:02.606132] Terminate:873 disable webserver ...
[21:29:02.606154] Terminate:876 end libupnp ...
21:25:22.933849 IP 10.0.0.39.53320 > 10.0.0.252.49152: Flags [P.], seq 1:422, ack 1, win 1369, options [nop,nop,TS val 7905118 ecr 866348880], length 421
E...W.@.@.. 
..'
....H........7....Y.......
.x.^3.oPGET /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3 HTTP/1.1
Host: 10.0.0.252:49152
Connection: keep-alive
User-Agent: Mozilla/5.0 (Linux; Android 5.1; Build/LMY47D) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/43.0.2357.90 Safari/537.36 CrKey/1.17.46918
Range: bytes=0-1
Accept: */*
Accept-Encoding: gzip, deflate
Accept-Language: en-GB
CAST-DEVICE-CAPABILITIES: {"bluetooth_supported":false,"display_supported":true}

21:25:22.933849 IP 10.0.0.252.49152 > 10.0.0.39.53320: Flags [.], ack 422, win 972, options [nop,nop,TS val 866348880 ecr 7905118], length 0
E..4X.@.@...
...
..'...H..7....R.....I.....
3.oP.x.^
21:25:22.934181 IP 10.0.0.252.49152 > 10.0.0.39.53320: Flags [P.], seq 1:277, ack 422, win 972, options [nop,nop,TS val 866348880 ecr 7905118], length 276
E..HX.@.@...
...
..'...H..7....R...........
3.oP.x.^HTTP/1.1 200 OK
CONTENT-TYPE: audio/mpeg
TRANSFER-ENCODING: chunked
DATE: Wed, 09 Mar 2016 21:25:22 GMT
LAST-MODIFIED: Thu, 01 Jan 1970 00:00:00 GMT
SERVER: Linux/3.2.0-4-amd64, UPnP/1.0, Portable SDK for UPnP devices/1.6.19
X-User-Agent: redsonic
CONNECTION: close

[...]

21:25:23.251735 IP 10.0.0.39.52676 > 10.0.0.252.49152: Flags [P.], seq 1:175, ack 1, win 1369, options [nop,nop,TS val 7905181 ecr 866348959], length 174
E.....@.@...
..'
........q=b.{+'...YE......
.x..3.o.GET /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3 HTTP/1.1
User-Agent: stagefright/1.2 (Linux;Android 5.1)
Host: 10.0.0.252:49152
Connection: Keep-Alive
Accept-Encoding: gzip

21:25:23.251771 IP 10.0.0.252.49152 > 10.0.0.39.52676: Flags [.], ack 175, win 972, options [nop,nop,TS val 866348960 ecr 7905181], length 0
E..4D.@.@...
...
..'.....{+'.q>......I.....
3.o..x..
21:25:23.252160 IP 10.0.0.252.49152 > 10.0.0.39.52676: Flags [P.], seq 1:277, ack 175, win 972, options [nop,nop,TS val 866348960 ecr 7905181], length 276
E..HD.@.@...
...
..'.....{+'.q>............
3.o..x..HTTP/1.1 200 OK
TRANSFER-ENCODING: chunked
CONTENT-TYPE: audio/mpeg
DATE: Wed, 09 Mar 2016 21:25:23 GMT
LAST-MODIFIED: Thu, 01 Jan 1970 00:00:00 GMT
SERVER: Linux/3.2.0-4-amd64, UPnP/1.0, Portable SDK for UPnP devices/1.6.19
X-User-Agent: redsonic
CONNECTION: close

21:25:23.252655 IP 10.0.0.39.52676 > 10.0.0.252.49152: Flags [.], ack 277, win 1386, options [nop,nop,TS val 7905181 ecr 866348960], length 0
E..4..@.@...
..'
........q>..{,;...je......
.x..3.o.
21:25:23.255169 IP 10.0.0.252.49152 > 10.0.0.39.52676: Flags [.], seq 277:1725, ack 175, win 972, options [nop,nop,TS val 866348961 ecr 7905181], length 1448
E...D.@.@..p
...
..'.....{,;.q>......8.....
3.o..x..100000
philippe44 commented 8 years ago

ah ... this is really unfortunate. The patch I did for libupnp works, in other words the AndroidTV tries to guess the size of the file to play by asking just one byte and I now answer correctly (saying basically : here is the 1 byte but I don't know the whole size) and then the AndroidTV request the whole file. Transfers starts normally now (sq_read logs) and then ... when I send the "play" request, it responds by an error ... this is totally unexpected. The last thing you can try is to not set the parameter to see if the fact that a set volume is sent just before the play command is causing a problem (if you do that from the web UI instead of changing the config file directly, this is the "LMS volume change" parameter)

gdhgdhgdh commented 8 years ago

Hm I tried again after stopping the bridge, setting LMS volume changes: ignore all changes, starting the bridge and then playing the same A-Ha track...

Unfortunately the result is just the same:

Starting Squeeze2cast: /var/lib/squeezeboxserver/cache/InstalledPlugins/Plugins/CastBridge/Bin/squeeze2cast-x86-64 -Z -I -f /var/log/squeezeboxserver/castbridge.log -d all=debug -x /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:07:57.076054] main:1175 Starting squeeze2cast version: v0.2.0.2-dev-1 (Mar  5 2016 @ 17:36:46)

[00:07:57.076263] decode_init:125 init decode, include codecs:  exclude codecs: 
[00:07:57.076300] main:1206 Buffer path /tmp
[00:07:57.094520] Initialize:807 UPnP init success - 10.0.0.252:49152
[00:07:57.094592] Initialize:831 WebServer enabled
[00:07:57.094607] Initialize:842 VirtualDir set for Squeezelite
[00:07:57.094619] Initialize:859 Callbacks registered for VirtualDir
[00:07:57.098484] UpdateMRThread:628 Begin Cast devices update
[00:08:12.130527] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:08:12.131254] UpdateMRThread:712 End Cast devices update 15033
[00:08:27.120714] UpdateMRThread:628 Begin Cast devices update
[00:08:42.150652] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:08:42.151560] UpdateMRThread:712 End Cast devices update 15031
[00:08:57.147748] UpdateMRThread:628 Begin Cast devices update
[00:09:12.178780] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:09:12.179697] UpdateMRThread:712 End Cast devices update 15032
[00:09:27.173931] UpdateMRThread:628 Begin Cast devices update
[00:09:42.205910] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:09:42.207567] UpdateMRThread:712 End Cast devices update 15034
[00:09:57.198469] UpdateMRThread:628 Begin Cast devices update
[00:10:12.230961] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:10:12.231666] UpdateMRThread:712 End Cast devices update 15033
[00:10:27.220192] UpdateMRThread:628 Begin Cast devices update
[00:10:42.250705] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:10:42.251440] UpdateMRThread:712 End Cast devices update 15031
[00:10:57.244277] UpdateMRThread:628 Begin Cast devices update
[00:11:12.278227] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:11:12.279055] UpdateMRThread:712 End Cast devices update 15034
[00:11:27.266361] UpdateMRThread:628 Begin Cast devices update
[00:11:42.297554] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:11:42.299000] UpdateMRThread:712 End Cast devices update 15032
[00:11:57.289517] UpdateMRThread:628 Begin Cast devices update
[00:12:12.322489] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:12:12.323419] UpdateMRThread:712 End Cast devices update 15034
[00:12:27.315511] UpdateMRThread:628 Begin Cast devices update
[00:12:42.344520] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:12:42.345240] UpdateMRThread:712 End Cast devices update 15030
[00:12:57.336748] UpdateMRThread:628 Begin Cast devices update
[00:13:12.366744] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:13:12.367454] UpdateMRThread:712 End Cast devices update 15031
[00:13:27.362765] UpdateMRThread:628 Begin Cast devices update
[00:13:42.394629] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:13:42.394983] UpdateMRThread:712 End Cast devices update 15032
[00:13:57.385527] UpdateMRThread:628 Begin Cast devices update
[00:14:12.808779] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:14:12.810281] UpdateMRThread:712 End Cast devices update 15425
[00:14:27.406855] UpdateMRThread:628 Begin Cast devices update
[00:14:42.833991] AddCastDevice:912 [0x6b2440]: adding renderer (Office TV)
[00:14:42.922255] CastConnect:380 [0x6b2440]: SSL connection opened [0x101a330]
[00:14:42.922581] SendCastMessage:265 [0x101a330]: Cast sending: {"type":"CONNECT"}
[00:14:42.923019] stream_thread_init:296 [0x652720] streambuf size: 2457600
[00:14:42.928022] output_mr_thread_init:780 [0x652720] init output media renderer
[00:14:42.928278] decode_thread_init:152 [0x652720]: init decode
[00:14:42.928394] discover_server:814 [0x652720] sending discovery
[00:14:42.929580] discover_server:843 [0x652720] got response from: 10.0.0.252:3483
[00:14:42.929681] slimproto_thread_init:1007 [0x652720] connecting to 10.0.0.252:3483
[00:14:42.929807] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:14:42.930393] UpdateMRThread:712 End Cast devices update 15524
[00:14:42.934941] slimproto:885 [0x652720] connected
[00:14:42.935061] sendHELO:131 [0x652720] mac: 1c:5a:6b:b9:89:e1
[00:14:42.935084] sendHELO:132 [0x652720] cap: Model=squeezelite,ModelName=SqueezeLite,AccuratePlayPoints=0,HasDigitalOut=0,MaxSampleRate=96000,pcm,aif,flc,mp3
[00:14:42.986318] process:562 [0x652720] strm
[00:14:42.986397] process_strm:241 [0x652720] strm command q
[00:14:42.986412] decode_flush:197 [0x652720]: decode flush
[00:14:42.986424] output_flush:858 [0x652720]: flush output buffer
[00:14:42.986467] sq_callback:247 [0x6b2440]: device off or not controlled by LMS
[00:14:42.987217] process:562 [0x652720] strm
[00:14:42.987255] process_strm:241 [0x652720] strm command q
[00:14:42.987267] decode_flush:197 [0x652720]: decode flush
[00:14:42.987279] output_flush:858 [0x652720]: flush output buffer
[00:14:42.987298] sq_callback:247 [0x6b2440]: device off or not controlled by LMS
[00:14:42.988335] process:562 [0x652720] setd
[00:14:42.988365] sendSETDName:226 set playername: Office TV
[00:14:42.988991] process:562 [0x652720] setd
[00:14:42.989238] process:562 [0x652720] aude
[00:14:42.989268] process_aude:446 [0x652720] on/off using aude 1
[00:14:42.989281] sq_callback:243 [0x6b2440]: device set on/off 1
[00:14:42.989829] process:562 [0x652720] audg
[00:14:42.989860] process_audg:473 [0x652720] (old) audg gainL: 128 gainR: 128
[00:14:44.002752] process:562 [0x652720] strm
[00:14:44.002864] process_strm:241 [0x652720] strm command t
[00:14:44.002907] sendSTAT:167 [0x652720] STAT: STMt
[00:14:45.976601] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:14:48.003427] process:562 [0x652720] strm
[00:14:48.003684] process_strm:241 [0x652720] strm command t
[00:14:48.003717] sendSTAT:167 [0x652720] STAT: STMt
[00:14:49.014100] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:14:52.002336] process:562 [0x652720] strm
[00:14:52.002588] process_strm:241 [0x652720] strm command t
[00:14:52.002622] sendSTAT:167 [0x652720] STAT: STMt
[00:14:52.019665] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:14:55.023882] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:14:56.002452] process:562 [0x652720] strm
[00:14:56.002825] process_strm:241 [0x652720] strm command t
[00:14:56.002861] sendSTAT:167 [0x652720] STAT: STMt
[00:14:57.431027] UpdateMRThread:628 Begin Cast devices update
[00:14:58.069446] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:14:59.602558] process:562 [0x652720] strm
[00:14:59.602676] process_strm:241 [0x652720] strm command q
[00:14:59.602892] decode_flush:197 [0x652720]: decode flush
[00:14:59.602917] output_flush:858 [0x652720]: flush output buffer
[00:14:59.602957] CastStop:203 [0x6b2440]: Stop req w/o session or connect
[00:14:59.689245] process:562 [0x652720] audg
[00:14:59.689383] process_audg:473 [0x652720] (old) audg gainL: 128 gainR: 128
[00:14:59.692287] process:562 [0x652720] strm
[00:14:59.692372] process_strm:238 [0x652720] strm command s
[00:14:59.692395] process_strm:309 [0x652720], strm s autostart: 1 transition period: 10 transition type: 0 codec: m
[00:14:59.692419] sendSTAT:165 [0x652720]: STAT:[STMf] msplayed 0
[00:14:59.692440] sendSTAT:167 [0x652720] STAT: STMf
[00:14:59.692499] codec_open:226 codec open: 'm'
[00:14:59.692556] stream_sock:392 [0x652720] connecting to 10.0.0.252:9000
[00:14:59.692747] stream_sock:421 [0x652720] header: GET /stream.mp3?player=1c:5a:6b:b9:89:e1 HTTP/1.0

[00:14:59.692862] sq_callback:262 [0x6b2440]: codec:m, ch:255, s:255, r:255
[00:14:59.801851] sq_get_metadata:583 [0x652720]: idx 0
    artist:a-ha
    album:Hunting High and Low
    title:Love Is Reason
    genre:Alternative
    duration:187.223
    size:0
    cover:http://10.0.0.252:9000/music/d5be518f/cover.jpg
[00:14:59.802209] SendCastMessage:265 [0x101a330]: Cast sending: {"type":"LAUNCH","requestId":1,"appId":"CC1AD845"}
[00:14:59.802278] CastLoad:142 [0x6b2440]: Queuing LOAD
[00:14:59.802294] sq_callback:305 [0x6b2440]: current URI set http://10.0.0.252:49152/LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3
[00:14:59.802324] sendSTAT:165 [0x652720]: STAT:[STMc] msplayed 0
[00:14:59.802338] sendSTAT:167 [0x652720] STAT: STMc
[00:14:59.802422] process:562 [0x652720] audg
[00:14:59.802438] process_audg:473 [0x652720] (old) audg gainL: 128 gainR: 128
[00:14:59.831282] stream_thread:181 [0x652720] headers: len: 116
HTTP/1.1 200 OK
Server: Logitech Media Server (7.9.0 - 1454098279)
Connection: close
Content-Type: audio/mpeg

[00:14:59.833727] sendRESP:196 RESP
[00:14:59.855713] CastSimple:177 [0x6b2440]: Queuing PLAY
[00:14:59.888839] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[00:15:00.001454] process:562 [0x652720] strm
[00:15:00.001521] process_strm:241 [0x652720] strm command t
[00:15:00.001533] sendSTAT:167 [0x652720] STAT: STMt
[00:15:00.401111] stream_thread:255 [0x652720] end of stream (t:3744476)
[00:15:00.401342] sendDSCO:183 DSCO: 0
[00:15:00.402446] process:562 [0x652720] strm
[00:15:00.402714] process_strm:238 [0x652720] strm command u
[00:15:00.402747] process_strm:285 [0x652720] unpause at: 0 now: 3735072992
[00:15:00.402770] sendSTAT:165 [0x652720]: STAT:[STMr] msplayed 0
[00:15:00.402790] sendSTAT:167 [0x652720] STAT: STMr
[00:15:00.451764] output_thru_thread:761 [0x652720] wrote total 3744476
[00:15:01.136057] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:02.258271] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:1)
[00:15:02.258389] CastSocketThread:667 [0x6b2440]: Receiver launched
[00:15:02.258534] SendCastMessage:265 [0x101a330]: Cast sending: {"type":"CONNECT","origin":{}}
[00:15:02.258780] SendCastMessage:265 [0x101a330]: Cast sending: {
 "media": {
  "contentId": "http://10.0.0.252:49152/LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3",
  "streamType": "BUFFERED",
  "contentType": "audio/mpeg",
  "metadata": {
   "trackNumber": 8,
   "metadataType": 3,
   "albumArtist": "a-ha",
   "albumName": "Hunting High and Low",
   "title": "Love Is Reason",
   "images": [
    {
     "url": "http://10.0.0.252:9000/music/d5be518f/cover.jpg"
    }
   ],
   "artist": "a-ha"
  }
 },
 "type": "LOAD",
 "requestId": 2,
 "sessionId": "A59762A5-8B3C-42A8-AE40-5BA882336CB6",
 "autoplay": false,
 "currentTime": 0.0
}
[00:15:02.634677] WebGetInfo:40 Headers: Connection: keep-alive
[00:15:02.634772] WebGetInfo:40 Headers: CAST-DEVICE-CAPABILITIES: {"bluetooth_supported":false,"display_supported":true}
[00:15:02.634803] sq_get_info:677 [0x652720]: GetInfo /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3 -2 audio/mpeg
[00:15:02.634826] WebGetInfo:63 [0x652720]: GetInfo /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3 -2 audio/mpeg
[00:15:02.635202] sq_open:743 [0x652720]: open
[00:15:02.635234] WebOpen:77 Webserver Open /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3
[00:15:02.635255] sq_seek:860 [0x652720]: seek 0 (c:16921056)
[00:15:02.635291] WebSeek:107 [0x653140]: seek 0, 1 (rc:0)
[00:15:02.635519] sq_read:934 [0x652720]: read 1 (a:1 r:1 w:100)
[00:15:02.635557] WebRead:94 read 1 on 1
[00:15:02.635798] sq_close:829 [0x652720]: read total:1
[00:15:02.635839] WebClose:118 webserver close
[00:15:02.918944] WebGetInfo:40 Headers: Connection: Keep-Alive
[00:15:02.919051] sq_get_info:677 [0x652720]: GetInfo /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3 -2 audio/mpeg
[00:15:02.919076] WebGetInfo:63 [0x652720]: GetInfo /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3 -2 audio/mpeg
[00:15:02.923649] sq_open:743 [0x652720]: open
[00:15:02.923734] WebOpen:77 Webserver Open /LMS2CAST/1c-5a-6b-b9-89-e1-idx-1.mp3
[00:15:02.931989] sq_read:934 [0x652720]: read 1048576 (a:1048576 r:1048576 w:100)
[00:15:02.932125] WebRead:94 read 1048576 on 1048576
[00:15:03.178982] sq_read:934 [0x652720]: read 1048576 (a:1048576 r:1048576 w:100)
[00:15:03.179063] WebRead:94 read 1048576 on 1048576
[00:15:03.417824] sq_read:934 [0x652720]: read 1048576 (a:1048576 r:1048576 w:100)
[00:15:03.417911] WebRead:94 read 1048576 on 1048576
[00:15:03.660928] CastSocketThread:628 [0x6b2440]: type:RECEIVER_STATUS (id:0)
[00:15:03.677941] CastSocketThread:625 [0x6b2440]: type:MEDIA_STATUS (id:2) IDLE
[00:15:03.678006] CastSocketThread:682 [0x6b2440]: Media session id 1
[00:15:03.678123] SendCastMessage:265 [0x101a330]: Cast sending: {"type":"SET_VOLUME","requestId":3,"mediaSessionId":1,"volume":{"level":0.500000,"muted":false}}
[00:15:03.678150] SendCastMessage:265 [0x101a330]: Cast sending: {"type":"PLAY","requestId":4,"mediaSessionId":1}
[00:15:03.719675] CastSocketThread:628 [0x6b2440]: type:INVALID_REQUEST (id:3)
[00:15:03.736457] CastSocketThread:628 [0x6b2440]: type:INVALID_REQUEST (id:4)
[00:15:03.772631] sq_read:934 [0x652720]: read 1048576 (a:1048576 r:598748 w:100)
[00:15:03.772707] WebRead:94 read 598748 on 1048576
[00:15:04.003332] process:562 [0x652720] strm
[00:15:04.003418] process_strm:241 [0x652720] strm command t
[00:15:04.003429] sendSTAT:167 [0x652720] STAT: STMt
[00:15:04.049681] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:04.049846] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:04.090558] sq_read:934 [0x652720]: read 1048576 (a:1048576 r:0 w:100)
[00:15:04.090612] sq_read:975 [0x652720]: read (end of track) w:100
[00:15:04.090622] WebRead:94 read 0 on 1048576
[00:15:04.090775] sq_close:829 [0x652720]: read total:3744476
[00:15:04.090790] WebClose:118 webserver close
[00:15:07.091765] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:07.092053] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:08.002723] process:562 [0x652720] strm
[00:15:08.002837] process_strm:241 [0x652720] strm command t
[00:15:08.002862] sendSTAT:167 [0x652720] STAT: STMt
[00:15:10.091763] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:10.092510] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:12.002642] process:562 [0x652720] strm
[00:15:12.003116] process_strm:241 [0x652720] strm command t
[00:15:12.003143] sendSTAT:167 [0x652720] STAT: STMt
[00:15:12.679333] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:15:12.680055] UpdateMRThread:712 End Cast devices update 15249
[00:15:13.092594] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:13.093414] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:16.003792] process:562 [0x652720] strm
[00:15:16.003907] process_strm:241 [0x652720] strm command t
[00:15:16.003932] sendSTAT:167 [0x652720] STAT: STMt
[00:15:16.094758] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:16.095043] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:19.145914] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:19.146214] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:20.003486] process:562 [0x652720] strm
[00:15:20.003731] process_strm:241 [0x652720] strm command t
[00:15:20.003764] sendSTAT:167 [0x652720] STAT: STMt
[00:15:22.191775] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:22.192121] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:24.001956] process:562 [0x652720] strm
[00:15:24.002117] process_strm:241 [0x652720] strm command t
[00:15:24.002146] sendSTAT:167 [0x652720] STAT: STMt
[00:15:25.199691] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:25.200239] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:27.454178] UpdateMRThread:628 Begin Cast devices update
[00:15:28.002521] process:562 [0x652720] strm
[00:15:28.003085] process_strm:241 [0x652720] strm command t
[00:15:28.003119] sendSTAT:167 [0x652720] STAT: STMt
[00:15:28.252245] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:28.252568] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:31.295047] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:31.295383] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:32.005853] process:562 [0x652720] strm
[00:15:32.005975] process_strm:241 [0x652720] strm command t
[00:15:32.006000] sendSTAT:167 [0x652720] STAT: STMt
[00:15:34.340087] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:34.340463] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:36.003794] process:562 [0x652720] strm
[00:15:36.003908] process_strm:241 [0x652720] strm command t
[00:15:36.003934] sendSTAT:167 [0x652720] STAT: STMt
[00:15:37.393995] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:37.394312] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:40.003520] process:562 [0x652720] strm
[00:15:40.003635] process_strm:241 [0x652720] strm command t
[00:15:40.003660] sendSTAT:167 [0x652720] STAT: STMt
[00:15:40.437906] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:40.440858] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:42.487104] UpdateMRThread:708 Updating configuration /var/lib/squeezeboxserver/prefs/castbridge.xml
[00:15:42.487886] UpdateMRThread:712 End Cast devices update 15033
[00:15:43.492282] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:43.492616] CastSocketThread:628 [0x6b2440]: type:PONG (id:0)
[00:15:44.003244] process:562 [0x652720] strm
[00:15:44.003366] process_strm:241 [0x652720] strm command t
[00:15:44.003393] sendSTAT:167 [0x652720] STAT: STMt

I don't really have a need to cast to Android TV - I just wanted to try and make the project more compatible :) Is there anything else that can be done here? The project works fine for casting to regular Chromecast and Chromecast Audio devices (including synced Groups!) - it'd just be nice to support all types.

Cheers, Gavin.

philippe44 commented 8 years ago

There is something strange because the volume command should not be sent when setting "ignore all changes" (I just re-checked my code ...) but anyway there is no reason why the AndroidTV would refuse the Volume & Play commands (INVALID REQUEST). Having said that, you helped me correcting one bug of libupnp and that's good but if this is fine for you, I'll stop here b/c if you don't really need to use the AndroidTV, I'll leave that correction to another time, when I'll get my hands on one. Currently, I'm pretty busy with with AirPlay bridge :-)

gdhgdhgdh commented 8 years ago

Heh yes it's a bit of a weird one.

Yes let's stop; I already have a squeeze client in the office, so the Android TV thing was just a 'nice to have' - thanks for your help on this :)