StartSession Request Timeout Occurs Every Time After Unplugging/Reconnecting A Phone

[adein]

Environment:

• iOS 8.3
• "Connected Vehicle" app
• SYNC3 TDK

Reproduction Steps:

1. Start the app on the phone, then connect to the TDK
2. Wait for the app to register with SYNC, then unplug the phone
3. Plug the phone back in

Expected Results:

App re-registers with Sync

Actual Results:

The SDL proxy connects to the Control Session, obtains a new protocol index, and closes that session. Then it starts a Data Session on the new protocol index, but does not receive a response to the StartSession request.

Recovery:

Terminate the app (swipe it out of the recent apps tray) and re-launch it.

Notes:

Based on viewing iAP traces, it does appear as if the headunit (SYNC3) is sending the response, but the proxy doesn't receive / process it somehow.

Log snippet:

06/19/15 08:57:45.261: [1] Accessory Connected, Opening in 7.883s
06/19/15 08:57:49.382: [3] SDLIAPTransport Dealloc
06/19/15 08:57:53.150: [1] Attempting To Connect
06/19/15 08:57:53.156: [1] Starting MultiApp Session
06/19/15 08:57:53.160: [1] SDLIAPSession initWithAccessory:<EAAccessory: 0x1700140a0> forProtocol:com.smartdevicelink.prot0
06/19/15 08:57:53.165: [1] Opening EASession withAccessory:Infotainment System forProtocol:com.smartdevicelink.prot0
06/19/15 08:57:53.172: [1] Created Session Object
06/19/15 08:57:53.179: [1] Input Stream Opened
06/19/15 08:57:53.185: [1] Output Stream Opened
06/19/15 08:57:53.186: [5] Control Stream Received Data
06/19/15 08:57:53.190: [1] Control Session Established
06/19/15 08:57:53.199: [5] Switching to protocol 1
06/19/15 08:57:53.204: [5] Output Stream Closed
06/19/15 08:57:53.209: [5] Input Stream Closed
06/19/15 08:57:53.230: [5] SDLIAPSession Dealloc
06/19/15 08:57:53.299: [1] Starting Data Session
06/19/15 08:57:53.305: [1] SDLIAPSession initWithAccessory:<EAAccessory: 0x1700140a0> forProtocol:com.smartdevicelink.prot1
06/19/15 08:57:53.311: [1] Opening EASession withAccessory:Infotainment System forProtocol:com.smartdevicelink.prot1
06/19/15 08:57:53.319: [1] Created Session Object
06/19/15 08:57:53.328: [1] Output Stream Opened
06/19/15 08:57:53.333: [1] Input Stream Opened
06/19/15 08:57:53.338: [1] Data Session Established
06/19/15 08:57:53.343: [1] StartSession (request)
06/19/15 08:57:53.347: [1] Warning: Tried to retrieve sessionID for serviceType 7, but no sessionID is saved for that service type.
06/19/15 08:58:03.352: [1] Start Session Timeout
06/19/15 08:58:03.468: [10] onProxyClosed
06/19/15 08:58:03.479: [10] Stop Proxy
06/19/15 08:58:03.484: [10] IAP Disconnecting
06/19/15 08:58:03.488: [10] Output Stream Closed
06/19/15 08:58:03.493: [10] Input Stream Closed
06/19/15 08:58:03.535: [10] SDLIAPSession Dealloc
06/19/15 08:58:03.554: [10] SDLIAPTransport Stopped Listening For Events
06/19/15 08:58:03.570: [10] SDLProtocol Dealloc
06/19/15 08:58:03.575: [10] SDLProxy Dealloc
06/19/15 08:58:03.612: [5] Start Proxy
06/19/15 08:58:03.617: [5] SDLIAPTransport Listening For Events
06/19/15 08:58:03.625: [5] SDLIAPTransport Init
06/19/15 08:58:03.630: [5] SDLProxy initWithTransport

[adein]

I'd appreciate it if this issue could be tested with a different app and a different environment to rule out the phone/app/TDK as the cause.

[adein]

Relevant log snippet from when the Data Session actually gets established:

06/19/15 08:57:35.563: [1] Opening EASession withAccessory:Infotainment System forProtocol:com.smartdevicelink.prot1
06/19/15 08:57:35.571: [1] Created Session Object
06/19/15 08:57:35.580: [1] Output Stream Opened
06/19/15 08:57:35.585: [1] Input Stream Opened
06/19/15 08:57:35.590: [1] Data Session Established
06/19/15 08:57:35.594: [1] StartSession (request)
06/19/15 08:57:35.598: [1] Warning: Tried to retrieve sessionID for serviceType 7, but no sessionID is saved for that service type.
06/19/15 08:57:35.671: [6] message complete. Version:2, compressed:0, frameType:Control(0), serviceType:7, frameData:StartSessionACK(2), sessionID:1, dataSize:4, messageID:16  Payload: 4 bytes.
06/19/15 08:57:35.675: [6] StartSession (response)
SessionId: 1 for serviceType 7
06/19/15 08:57:35.684: [6] onProxyOpened

[adein]

I just did some testing, and I think I have some more insight.

I built and ran the SDL Example app and ran it on the same phone/TDK; it worked fine.

I then noticed that the other app I had been using was trying to send RPCs after the proxy was disconnected. E.g., it was sending a Show and an UnsubscribeVehicleData RPC after the onProxyClosed, due to a bug in the code logic. I'm not sure which proxy instance it was actually sending this through (old or new).

I put in a simple BOOL to have the app check proxy connection state before sending RPCs, and now it seems to be working fine.

Obviously this is a case of an app doing a bad thing, but it seems like something that the proxy should be able to prevent? I'm not exactly sure where or what in the proxy is getting messed up to create this behavior, but this seems like another item to discuss as a future improvement.

[adein]

I was able to reproduce the behavior with the SyncProxyTester app by doing the following:

1. Start the app and connect to SYNC
2. Once the app is connected and registered, unplug the phone
3. Send a Show RPC while the phone is unplugged (which will try to send it using the new proxy instance)
4. Plug in the phone to SYNC

At step 4, the app shows that the StartSession request was sent, but believes that no response came back. The SPT app then times-out the request, and recycles the proxy.

[joeljfischer]

I created #241 to track the underlying error here, and linked back. I think we can close this issue, unless you have anything else.

[adein]

Sounds good. I'll close this one.