[Android Apps and Games] luisbona:
Similar problem

I'm trying to debug a similar problem with chromecast audio, no answers so far.

First time I launch bubbleupnpserver it works like a charm. But if I stop the render from the android app and a time later try to use it again I receive a message of "action timeout" and next "launch receiver already in progress". In this cases I still able to cast to the "raw" audiocast device. Restarting server causes the "openhome" wrap to work again for a while.

I did further debug and apparently I discovered something wrong. From my log, first time I use my "openhome wrapper" everything is okay, then I stop it and receive:

[cling-394 (635) ] INFO - 08:07:58.137 - z : stopping task GetTransportStateTask
[cling-399 (Pause) (645) ] INFO - 08:07:58.137 - b : Cozinha: pause()
[cling-399 (Pause) (645) ] INFO - 08:07:58.137 - b : send message: sourceId=client-567673 destinationId=c803c3df-0386-4aea-9f04-d2a1031e5946 namespace=urn:x-cast:com.google.cast.media data={"requestId":4672,"type":"PAUSE","mediaSessionId":29}
[cling-394 (635) ] INFO - 08:07:58.138 - b : Cozinha (DLNA): waitForTransportState: waiting for Paused
[CastSocketRead (136) ] INFO - 08:07:58.145 - b$1 : recv message: sourceId=c803c3df-0386-4aea-9f04-d2a1031e5946 destinationId=* namespace=urn:x-cast:com.google.cast.media data={"type":"MEDIA_STATUS","status":[{"mediaSessionId":29,"playbackRate":1,"playerState":"PAUSED","currentTime":36.14507,"supportedMediaCommands":15,"volume":{"level":1,"muted":false},"currentItemId":29,"repeatMode":"REPEAT_OFF"}],"requestId":4672}
[CastSocketRead (136) ] INFO - 08:07:58.145 - b : Cozinha: player state: PAUSED
[CastSocketRead (136) ] INFO - 08:07:58.145 - b : Cozinha: stopped get current time task
[CastSocketRead (136) ] INFO - 08:07:58.145 - b : Cozinha: Current state is: PLAYING, changing to new state: PAUSED_PLAYBACK
[cling-394 (635) ] INFO - 08:07:58.238 - b : Cozinha (DLNA): waitForTransportState: done waiting for Paused
[cling-394 (635) ] INFO - 08:07:58.238 - b : Cozinha (DLNA): TransportState: Paused
[cling-394 (635) ] INFO - 08:07:58.239 - z : started task GetTransportStateTask
[main (1) ] INFO - 08:07:58.240 - a : setGaplessTransportStateChange: false
[CastSocketRead (136) ] INFO - 08:08:03.501 - b$1 : recv message: sourceId=Tr@n$p0rt-0 destinationId=Tr@n$p0rt-0 namespace=urn:x-cast:com.google.cast.tp.heartbeat data={"type":"PING"}
[CastSocketRead (136) ] INFO - 08:08:03.502 - b : send message: sourceId=Tr@n$p0rt-0 destinationId=Tr@n$p0rt-0 namespace=urn:x-cast:com.google.cast.tp.heartbeat data={"type":"PONG"}
<.... PING and PONG goes on until >
[CastSocketRead (136) ] INFO - 09:12:58.214 - b$1 : recv message: sourceId=c803c3df-0386-4aea-9f04-d2a1031e5946 destinationId=client-567673 namespace=urn:x-cast:com.google.cast.tp.connection data={"type":"CLOSE"}
[CastSocketRead (136) ] INFO - 09:12:58.215 - b : send message: sourceId=client-567673 destinationId=c803c3df-0386-4aea-9f04-d2a1031e5946 namespace=urn:x-cast:com.google.cast.media data={"requestId":4673,"type":"STOP","mediaSessionId":29}
[CastSocketRead (136) ] INFO - 09:12:58.215 - b : Cozinha: Current state is: PAUSED_PLAYBACK, changing to new state: STOPPED
[CastSocketRead (136) ] WARNING - 09:12:58.216 - b : Cozinha: player closed
[CastSocketRead (136) ] INFO - 09:12:58.219 - b$1 : recv message: sourceId=c803c3df-0386-4aea-9f04-d2a1031e5946 destinationId=client-567673 namespace=urn:x-cast:com.google.cast.tp.connection data={"type":"CLOSE"}

Few hours latter I try to use the "cozinha" openhome render wrapper again and then I receive an exception from the socket saying it is closed (it is okay, since the audiocast asked for it.

I dont know what is wrong, audiocast asking for close, or bubble who "forgets" the socket was closed:

[cling-692 (940) ] INFO - 20:00:33.695 - b : Cozinha (DLNA): waitForTransportState: waiting for Stopped
[cling-692 (940) ] INFO - 20:00:33.696 - b : Cozinha (DLNA): waitForTransportState: done waiting for Stopped
[cling-692 (940) ] INFO - 20:00:33.697 - a : SetAVTransportURI <...cut >
[cling-683 (SetAVTransportURI] INFO - 20:00:33.698 - b : Cozinha: setAVTransportURI: <...cut>
[cling-683 (SetAVTransportURI] INFO - 20:00:33.701 - b : Cozinha: got mime-type from protocolInfo
[cling-683 (SetAVTransportURI] INFO - 20:00:33.701 - b : Cozinha: mime-type: audio/x-flac
[cling-683 (SetAVTransportURI] INFO - 20:00:33.701 - b : Cozinha: should proxy: false
[cling-692 (940) ] INFO - 20:00:33.701 - b : Cozinha (DLNA): play: waiting 100 ms...
[cling-690 (Play) (938) ] INFO - 20:00:33.802 - b : Cozinha: play()
[cling-690 (Play) (938) ] INFO - 20:00:33.802 - b : Cozinha: launch receiver...
[cling-690 (Play) (938) ] INFO - 20:00:33.802 - b : send message: sourceId=sender-0 destinationId=receiver-0 namespace=urn:x-cast:com.google.cast.receiver data={"requestId":5,"appId":"65C370FF","type":"LAUNCH"}
[cling-692 (940) ] INFO - 20:00:33.802 - b : Cozinha (DLNA): waitForTransportState: waiting for Playing
[CastSocketRead (136) ] WARNING - 20:00:33.808 - b$2 : error: java.net.SocketException: Connection reset
[CastSocketRead (136) ] WARNING - 20:00:33.808 - b : Cozinha: platform error: Connection reset
[CastSocketRead (136) ] INFO - 20:00:33.808 - b : Cozinha: disconnecting...
[CastSocketRead (136) ] INFO - 20:00:33.809 - b : closing connection ...
[CastSocketRead (136) ] INFO - 20:00:33.809 - b : Cozinha: Current state is: STOPPED, changing to new state: STOPPED
[CastSocketRead (136) ] INFO - 20:00:33.809 - b : Cozinha: disconnected
[CastSocketRead (136) ] INFO - 20:00:33.812 - m : I/O exception (java.net.SocketException) caught when processing request: Connection reset
[CastSocketRead (136) ] INFO - 20:00:33.812 - m : Retrying request
[CastSocketRead (136) ] WARNING - 20:00:33.822 - b$3 : connection closed
[CastSocketRead (136) ] INFO - 20:00:33.825 - c$3 : platform sender: closed

Looking netstat is possible to see that the connections (port 8008 and 8009) are gone. I believe bubbleupnpserver should retry to establish the connection.

~