Closed GoogleCodeExporter closed 8 years ago
I have only seen this happen during the initial sender connection, when the app
is started. The sender kicks off the app on the receiver, gets the didConnect
callback and fires a message - in some cases the message is received by the
receiver prior to the sender connected event.
I have yet to see this occur when didConnect gets called after the app comes
back from background.
Original comment by m...@juko.fm
on 27 Oct 2014 at 12:28
Just tried 20 consecutive times, selecting the cast device, seeing if the first
message got through OK, and disconnecting. In 3 times out of 20 I saw the order
of events above - message received by the receiver before the sender connected
event seen by the receiver.
Original comment by m...@juko.fm
on 27 Oct 2014 at 1:02
When logging the timestamps of the connected event and the first message in the
receiver, under normal circumstances I see the first message arrive just a few
milliseconds (e.g. ~10ms or less) after the sender connected event. This seems
way too fast for a home wifi network - I would expect there to be a bit more
handshaking going on and a longer latency between these two events.
In the erroneous case I see the sender connected event also just a few
milliseconds after receiving the first message. Seems like the sender library
is a bit too optimistic regarding when connection actually took place and
didConnect is fired too soon.
I'm guessing the sender library is a bit optimistic regarding when the
connection actually takes place, and fires didConnect a bit too soon.
Original comment by m...@juko.fm
on 27 Oct 2014 at 4:49
I was unable to reproduce this using the demo projects for iOS (CastVideos-ios)
and the receiver (Cast-Player-Sample) on the GitHub Cast account.
Is this still an issue for your project?
Please refer to this link for the demo projects: https://github.com/googlecast
Original comment by christia...@google.com
on 4 Nov 2014 at 9:12
Absolutely still an issue. Thus for iOS I'm delaying the sending of the initial
message by 100ms after didConnect. CastVideos-ios doesn't use sendTextMessage -
perhaps describe what you're doing exactly?
Additionally, this is clearly a subtle timing bug so I'm not surprised it is
difficult to reproduce. For me this occurs on the iOS simulator.
Original comment by m...@juko.fm
on 4 Nov 2014 at 9:39
I'm having trouble reproing this as well, with a sample that is connecting a
GCKCastChannel in didConnectToCastApplication and sending a message in the
channel's didConnect method (all in the simulator). AFAICS we always get a
postitve response from application connected before excuting. I can see a
potential for a race though, if there is retransmission due to loss. Can you
post a trace from the receiver with debug level logging enabled?
Original comment by ianbar...@google.com
on 7 Nov 2014 at 12:34
Looking at it some more, I am relatively confident that the order of sent
messages should be correct from the SDK side, so my inclination is that
something is happening receiver side.
Original comment by ianbar...@google.com
on 7 Nov 2014 at 12:43
Here is the failing debug sequence:
[ 1.272s] [cast.receiver.CastReceiverManager] Version: 2.0.0.0012 cast_receiver.js:18
[ 1.296s] [cast.receiver.IpcChannel] Opening message bus websocket cast_receiver.js:18
[ 1.305s] [goog.net.WebSocket] Opening the WebSocket on ws://localhost:8008/v2/ipc cast_receiver.js:18
The page at 'https://xxxxxxx' was loaded over HTTPS, but ran insecure content
from 'ws://localhost:8008/v2/ipc': this content should also be loaded over
HTTPS.
receiver:1
Connecting to a non-secure WebSocket server from a secure origin is deprecated.
receiver:1
[ 1.356s] [goog.net.WebSocket] WebSocket opened on ws://localhost:8008/v2/ipc cast_receiver.js:18
[ 1.372s] [cast.receiver.IpcChannel] IpcChannel opened cast_receiver.js:18
[ 1.385s] [cast.receiver.CastMessageBus] Dispatching CastMessageBus message cast_receiver.js:18
[ 1.400s] [cast.receiver.CastReceiverManager] Underlying message bus is open cast_receiver.js:18
[ 1.404s] [cast.receiver.IpcChannel] IPC message sent: {"namespace":"urn:x-cast:com.google.cast.system","senderId":"SystemSender","data":"{\"type\":\"ready\",\"activeNamespaces\":[\"urn:x-cast:com.xxxx.yyy\"],\"version\":\"2.0.0\",\"messagesVersion\":\"1.0\"}"} cast_receiver.js:18
[ 1.410s] [cast.receiver.IpcChannel] IPC message sent: {"namespace":"urn:x-cast:com.google.cast.system","senderId":"SystemSender","data":"{\"type\":\"startheartbeat\",\"maxInactivity\":10}"} cast_receiver.js:18
[ 1.442s] [cast.receiver.IpcChannel] Received message: {"data":"{\"applicationId\":\"XXXX\",\"applicationName\":\"zzzz\",\"launchingSenderId\":\"52:DC1BAF4B-9790-432B-A83F-E20D6FF9B292\",\"messagesVersion\":\"1.0\",\"sessionId\":\"8B481BCE-A89D-469F-0AE2-0E87127F25CE\",\"type\":\"ready\",\"version\":\"1.0\"}","namespace":"urn:x-cast:com.google.cast.system","senderId":"SystemSender"} cast_receiver.js:18
[ 1.445s] [cast.receiver.CastMessageBus] Dispatching CastMessageBus message cast_receiver.js:18
[ 1.455s] [cast.receiver.CastReceiverManager] Dispatching CastReceiverManager system ready event cast_receiver.js:18
[ 1.466s] [cast.receiver.IpcChannel] Received message: {"data":"{\"type\":\"connected\"}","namespace":"urn:x-cast:com.xxxx.yyy","senderId":"52:DC1BAF4B-9790-432B-A83F-E20D6FF9B292"} cast_receiver.js:18
[ 1.471s] [cast.receiver.CastMessageBus] Dispatching CastMessageBus message cast_receiver.js:18
message received in service:
{"type":"message","H":false,"defaultPrevented":false,"lb":true,"senderId":"52:DC
1BAF4B-9790-432B-A83F-E20D6FF9B292","data":{"type":"connected"}}
angular.min.js:63
sending message to Id: 52:DC1BAF4B-9790-432B-A83F-E20D6FF9B292 msg:
{"type":"idle"} angular.min.js:63
failed to getCastChannel for 52:DC1BAF4B-9790-432B-A83F-E20D6FF9B292
angular.min.js:63
error sending to: 52:DC1BAF4B-9790-432B-A83F-E20D6FF9B292 message: [object
Object] angular.min.js:63
Original comment by m...@juko.fm
on 7 Nov 2014 at 7:18
For reference here is the successful sequence:
[ 1.048s] [cast.receiver.CastReceiverManager] Version: 2.0.0.0012 cast_receiver.js:18
[ 1.060s] [cast.receiver.IpcChannel] Opening message bus websocket cast_receiver.js:18
[ 1.066s] [goog.net.WebSocket] Opening the WebSocket on ws://localhost:8008/v2/ipc cast_receiver.js:18
[ 1.099s] [goog.net.WebSocket] WebSocket opened on ws://localhost:8008/v2/ipc cast_receiver.js:18
[ 1.104s] [cast.receiver.IpcChannel] IpcChannel opened cast_receiver.js:18
[ 1.120s] [cast.receiver.CastMessageBus] Dispatching CastMessageBus message cast_receiver.js:18
[ 1.131s] [cast.receiver.CastReceiverManager] Underlying message bus is open cast_receiver.js:18
[ 1.141s] [cast.receiver.IpcChannel] IPC message sent: {"namespace":"urn:x-cast:com.google.cast.system","senderId":"SystemSender","data":"{\"type\":\"ready\",\"activeNamespaces\":[\"urn:x-cast:com.xxxx.yyy\"],\"version\":\"2.0.0\",\"messagesVersion\":\"1.0\"}"} cast_receiver.js:18
[ 1.145s] [cast.receiver.IpcChannel] IPC message sent: {"namespace":"urn:x-cast:com.google.cast.system","senderId":"SystemSender","data":"{\"type\":\"startheartbeat\",\"maxInactivity\":10}"} cast_receiver.js:18
[ 1.185s] [cast.receiver.IpcChannel] Received message: {"data":"{\"applicationId\":\"XXXX\",\"applicationName\":\"zzzz\",\"launchingSenderId\":\"69:10073353-AD76-4960-B61E-AA79B96E2AA9\",\"messagesVersion\":\"1.0\",\"sessionId\":\"58EF4B4D-E4E7-4576-C22E-D303AE6879A1\",\"type\":\"ready\",\"version\":\"1.0\"}","namespace":"urn:x-cast:com.google.cast.system","senderId":"SystemSender"} cast_receiver.js:18
[ 1.192s] [cast.receiver.CastMessageBus] Dispatching CastMessageBus message cast_receiver.js:18
[ 1.195s] [cast.receiver.CastReceiverManager] Dispatching CastReceiverManager system ready event cast_receiver.js:18
[ 1.206s] [cast.receiver.IpcChannel] Received message: {"data":"{\"senderId\":\"69:10073353-AD76-4960-B61E-AA79B96E2AA9\",\"type\":\"senderconnected\",\"userAgent\":\"iOS CastSDK,2.4.0,iPhone Simulator,iPhone OS,8.1\"}","namespace":"urn:x-cast:com.google.cast.system","senderId":"SystemSender"} cast_receiver.js:18
[ 1.209s] [cast.receiver.CastMessageBus] Dispatching CastMessageBus message cast_receiver.js:18
[ 1.211s] [cast.receiver.CastReceiverManager] Dispatching CastReceiverManager sender connected event [69:10073353-AD76-4960-B61E-AA79B96E2AA9] cast_receiver.js:18
[ 1.214s] [cast.receiver.CastMessageBus] Registering sender [urn:x-cast:com.xxxx.yyy, 69:10073353-AD76-4960-B61E-AA79B96E2AA9] cast_receiver.js:18
[ 1.217s] [cast.receiver.IpcChannel] Received message: {"data":"{\"type\":\"connected\"}","namespace":"urn:x-cast:com.xxxx.yyy","senderId":"69:10073353-AD76-4960-B61E-AA79B96E2AA9"} cast_receiver.js:18
[ 1.221s] [cast.receiver.CastMessageBus] Dispatching CastMessageBus message cast_receiver.js:18
message received in service:
{"type":"message","H":false,"defaultPrevented":false,"lb":true,"senderId":"69:10
073353-AD76-4960-B61E-AA79B96E2AA9","data":{"type":"connected"}}
angular.min.js:63
sending message to Id: 69:10073353-AD76-4960-B61E-AA79B96E2AA9 msg:
{"type":"idle"} angular.min.js:63
castChannel: urn:x-cast:com.xxxx.yyy angular.min.js:63
[ 1.233s] [cast.receiver.IpcChannel] IPC message sent: {"namespace":"urn:x-cast:com.xxx.yyy","senderId":"69:10073353-AD76-4960-B61E-AA79B96E2AA9","data":"{\"type\":\"idle\"}"}
sent angular.min.js:63
Original comment by m...@juko.fm
on 7 Nov 2014 at 7:28
Here are the differences I'm seeing:
1. In the failing sequence I get a warning about the page being loaded
securely, but running insecure content on the websocket. Obviously the page was
loaded identically in both cases (over https). In fact, the app on iOS was not
even reloaded, these prints are from successive connects/disconnects from
Chromecast.
2. In the failed case we don't (ever) get the senderconnected message in the
com.google.cast.system namespace, and the first message we get is the
application message ("connected") and this is of course a bug.
Original comment by m...@juko.fm
on 7 Nov 2014 at 7:36
My mistake on the insecure content warning: it occurs in the successful case
too, but I mistakenly filtered that log message in the second case. So the only
difference is that on occasion the application message is received prior to
senderconnected (which is never received in that case).
Original comment by m...@juko.fm
on 7 Nov 2014 at 7:59
For reference, also note I saw errors in the opposite direction, this time to
an Android sender:
https://github.com/googlecast/CastCompanionLibrary-android/issues/123
Due to this error I changed my app logic so the sender sends the initial
message (thus the current ticket).
Original comment by m...@juko.fm
on 7 Nov 2014 at 8:09
My Chromecast was updated last night to firmware 22062 and since then I can't
repro this..... does this make sense to the Google team?
Original comment by m...@juko.fm
on 8 Nov 2014 at 11:38
Original comment by christia...@google.com
on 21 Nov 2014 at 8:07
Original issue reported on code.google.com by
m...@juko.fm
on 27 Oct 2014 at 11:46