iOS: sending a message immediately after GCKCastChannel.didConnect occasionally fails

[GoogleCodeExporter]

What steps will reproduce the problem?
1. Receive didConnectToCastApplication
2. Initialize the channel and add to deviceManager
3. Receive GCKCastChannel.didConnect callback
4. Immediately send a message
5. The receiver logs show the following, in about 1 in 20 times (when sender is 
iOS simulator)

 [  1.056s] [goog.net.WebSocket] Opening the WebSocket on ws://localhost:8008/v2/ipc cast_receiver.js:18
The page at 'https://blahblah.net/cast/blahreceiver' 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.095s] [goog.net.WebSocket] WebSocket opened on ws://localhost:8008/v2/ipc cast_receiver.js:18
message received in service: 
{"type":"message","H":false,"defaultPrevented":false,"lb":true,"senderId":"31:AD
7C955F-5E3E-4302-BAF7-294A61531F16","data":{"type":"connected"}} 
angular.min.js:63
message received, data: {"type":"connected"} angular.min.js:63
sending message to Id: 31:AD7C955F-5E3E-4302-BAF7-294A61531F16 msg: 
{"type":"idle"} angular.min.js:63
failed to getCastChannel for 31:AD7C955F-5E3E-4302-BAF7-294A61531F16 
angular.min.js:63
error sending to: 31:AD7C955F-5E3E-4302-BAF7-294A61531F16 message: [object 
Object] angular.min.js:63
Sender connected: 
{"type":"senderconnected","H":false,"defaultPrevented":false,"lb":true,"data":"3
1:AD7C955F-5E3E-4302-BAF7-294A61531F16","senderId":"31:AD7C955F-5E3E-4302-BAF7-2
94A61531F16","userAgent":"iOS CastSDK,2.4.0,iPhone Simulator,iPhone OS,8.1"} 

What is the expected output? What do you see instead?
I would expect that the sender connected event would show on the receiver prior 
to receiving a message from the iOS sender. This is usually what happens, but 
rarely we also see the scenario above (message received, then a failed send 
message, and only later the sender connected event.

What version of the product are you using? On what operating system?
iOS sender SDK 2.4.0, iOS 8.1 simulator (see the log)

Please provide any additional information below.

Original issue reported on code.google.com by m...@juko.fm on 27 Oct 2014 at 11:46

[GoogleCodeExporter]

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

[GoogleCodeExporter]

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

[GoogleCodeExporter]

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

[GoogleCodeExporter]

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

• Changed state: NeedInfo

[GoogleCodeExporter]

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

[GoogleCodeExporter]

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

[GoogleCodeExporter]

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

[GoogleCodeExporter]

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

[GoogleCodeExporter]

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

[GoogleCodeExporter]

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

[GoogleCodeExporter]

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

[GoogleCodeExporter]

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

[GoogleCodeExporter]

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

[GoogleCodeExporter]

Original comment by christia...@google.com on 21 Nov 2014 at 8:07

• Changed state: Done