search

smartdevicelink / sdl_core

SmartDeviceLink In-Vehicle Software and Sample HMI
BSD 3-Clause "New" or "Revised" License
241 stars 244 forks source link

Waze (i): nothing happens after selecting on mobile apps screen. #3054

Closed kekapare closed 4 years ago

kekapare commented 5 years ago

Bug Report

When iPhone is connected to the HU, on selecting Waze app, nothing happens i.e. app does not launch.

Analysis from the attached log:

58431 2019/09/09 13:16:23.240676 5713.9445 205 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [1318]:[posix_thread.cc:279] :join::Waiting for #1136194544 finished iteration in thread #1920226288

58466 2019/09/09 13:16:23.285566 5713.9487 239 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[application_state.cc:110] :GetState::Getting postponed state.

From the above two logs, thread # 1318 is blocked and waiting for thread # 13336(1136194544) to come out and unblock it.

But from available log, it shows that 13336 is blocked and is not coming out.

55149 2019/09/09 13:16:21.053315 5710.9304 155 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[posix_thread.cc:93] :threadFunc::Thread #1136194544 iteration 55167 2019/09/09 13:16:21.061840 5710.9323 173 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[posixthread.cc:98] :threadFunc::Thread #1136194544 execute. stopped = 0; finalized_ = 0 55169 2019/09/09 13:16:21.062956 5710.9325 175 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[timer.cc:205] :threadMain::Milliseconds left to wait: 3000 58398 2019/09/09 13:16:23.147278 5713.9330 172 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[timer.cc:209] :threadMain::Timer has finished counting. Timeout (ms): 3000 . . . 58456 2019/09/09 13:16:23.274790 5713.9480 229 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[application_state.cc:113] :GetState::Getting current state. 58457 2019/09/09 13:16:23.280842 5713.9480 230 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[state_controller_impl.cc:461] :OnStateChanged::old: hmi_level 0, audio_state 0, system_context 0 58458 2019/09/09 13:16:23.281627 5713.9481 231 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[state_controller_impl.cc:467] :OnStateChanged::new: hmi_level 0, audio_state 0, system_context 0 58459 2019/09/09 13:16:23.282056 5713.9481 232 ECU1 ALCO JOUR 1146 log error verbose 1 SDLCore_4.2.091517.5022572 [13336]:[state_controller_impl.cc:477] :OnStateChanged::Status not changed 58460 2019/09/09 13:16:23.282494 5713.9482 233 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[application_state.cc:110] :GetState::Getting postponed state. 58461 2019/09/09 13:16:23.283657 5713.9483 234 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[application_state.cc:110] :GetState::Getting postponed state. 58462 2019/09/09 13:16:23.284125 5713.9484 235 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[application_state.cc:110] :GetState::Getting postponed state. 58463 2019/09/09 13:16:23.284452 5713.9485 236 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[application_state.cc:110] :GetState::Getting postponed state. 58464 2019/09/09 13:16:23.284761 5713.9486 237 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[application_state.cc:110] :GetState::Getting postponed state. 58465 2019/09/09 13:16:23.285246 5713.9487 238 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[application_state.cc:110] :GetState::Getting postponed state. 58466 2019/09/09 13:16:23.285566 5713.9487 239 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[application_state.cc:110] :GetState::Getting postponed state.

Can you please let us know the reason for 13336 not coming out and finishing iteration.

Its very hard to reproduce issue. waze_not_opening.txt .

Reproduction Steps
  1. Waze is running on phone HMI.
  2. Mobile apps screen is shown on HU.
  3. Language set to English.
  4. Try to launch waze from HU
Expected Behavior

Waze should launch.

Observed Behavior

Nothing happens

OS & Version Information
Jack-Byrne commented 5 years ago

From those logs I see

  1. BasicCommunication.OnAppDeactivated
  2. BasicCommunication.OnAppActivated
  3. BasicCommunication.ActivateApp
  4. UI.OnSystemContext
  5. BasicCommunication.OnExitApplication
  6. Navigation.OnVideoDataStreaming
  7. Navigation.StopStream
  8. SDL.ActivateApp

Why/when is the HMI sending BasicCommunication.OnExitApplication? It looks like the app started to stream but then stopped very shortly after.

Have you tried your setup with any other app?

Jack-Byrne commented 5 years ago

To check that the app is "activated" correctly, see if SDL Core tries to send the app OnHMIStatus: FULL

kekapare commented 5 years ago

@JackLivio :

Thank you for the response.

Q:Why/when is the HMI sending BasicCommunication.OnExitApplication? It looks like the app started to stream but then stopped very shortly after.

[Kedar] This happens way later time.

108260 2019/09/09 13:17:38.602238 5792.5370 1 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [1325]:[application_manager_impl.cc:1932] :ConvertMessageToSO:: Message to convert: protocol 0; json { "jsonrpc" : "2.0", "method" : "BasicCommunication.OnExitApplication", "params" : { "appID" : 386525063, "reason" : "USER_EXIT" } }

Initially thread is blocked as seen below before more than 1 minute of the HMI calling OnExitApplication. 58466 2019/09/09 13:16:23.285566 5713.9487 239 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [13336]:[application_state.cc:110] :GetState::Getting postponed state.

Also, immediately after this, we see the thread #1318 is also blocked which is not processing the received data.

58483 2019/09/09 13:16:23.312164 5713.9911 0 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [1317]:[transport_manager_impl.cc:916] :Handle::event_type = ON_RECEIVED_DONE 58537 2019/09/09 13:16:23.420435 5714.2012 70 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [1317]:[transport_manager_impl.cc:916] :Handle::event_type = ON_RECEIVED_DONE 58554 2019/09/09 13:16:23.441434 5714.2557 87 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [1317]:[transport_manager_impl.cc:916] :Handle::event_type = ON_RECEIVED_DONE 58571 2019/09/09 13:16:23.482228 5714.3224 104 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [1317]:[transport_manager_impl.cc:916] :Handle::event_type = ON_RECEIVED_DONE 58588 2019/09/09 13:16:23.521201 5714.3813 121 ECU1 ALCO JOUR 1146 log debug verbose 1 SDLCore_4.2.091517.5022572 [1317]:[transport_manager_impl.cc:916] :Handle::event_type = ON_RECEIVED_DONE

Q:Have you tried your setup with any other app? [Kedar] - yes, we tried to reproduce the issue with Waze app as well as Antelope/Sygic app. The issue is not reproducible on our setup.

Q:To check that the app is "activated" correctly, see if SDL Core tries to send the app OnHMIStatus: FULL [Kedar] - As seen in below log, SDL has already sent the HMI notification with FULL before thread 13336 is blocked. 95576 2019/09/09 13:17:10.967394 5764.8626 50 ECU1 ALCO JOUR 1146 log info verbose 1 SDLCore_4.2.091517.5022572 [1324]:[mobile_message_handler.cc:131] :HandleOutgoingMessageProtocol::Outgoing RPC_INFO: 1, Notification, 32768, -1, { "audioStreamingState" : "AUDIBLE", "hmiLevel" : "FULL", "systemContext" : "MAIN" }

Summary :

OnExitApplication is triggered at time 13:17:38 And thread 13336 and 1318 goes in deadlock state from the timestamp 13:16:23 OnExitApplication is triggered by HMI after one minute from the problem. As explained above, thread 13336 and 1318 are in deadlocked state. Can you please review the part of log near this and provide your opinion on this behavior?

Thank you, Kedar

kekapare commented 5 years ago

@JackLivio : Can you please provide your feedback on the same? Thank you, Kedar

Jack-Byrne commented 5 years ago

@kekapare I am not 100% sure but I think the issue is due to a deadlock on this line

https://github.com/smartdevicelink/sdl_core/blob/2392564774a6b3c0dc1e92dc19cf495f733b5100/src/components/application_manager/src/application_impl.cc#L477

Thread 13336 last prints a log > GetState::Getting postponed state. and then nothing happens. By tracing the code back I arrived at this SuspendStreaming function that sets the state but never sends the RPC Navigation.OnAudioDataStreaming. Therefore I think the thread is blocked while trying to obtain the audio_streaming_suspendlock

A fix could be to remove the line 

sync_primitives::AutoLock lock(audio_streaming_suspended_lock_);

Also in application_impl.h change

  bool audio_streaming_suspended_;

to

 std::atomic<bool> audio_streaming_suspended_;
Jack-Byrne commented 5 years ago

Also take a look at this issue. From the logs this looks like the problem you might be experiencing?

https://github.com/smartdevicelink/sdl_core/issues/1782

and possible fix for the issue

https://github.com/smartdevicelink/sdl_core/pull/1783

Jack-Byrne commented 5 years ago

Here is another fix that might be worth trying: https://github.com/smartdevicelink/sdl_core/pull/2193

kekapare commented 4 years ago

@JackLivio : Thanks for the feedback. Will check it and get back to you. Thank you.

E-SAITO-TMC commented 4 years ago

@theresalech -san This issue is a medium priority for Toyota. I would like know if this issue occur in the latest version. And could you please include this issue in your plan? Thank you.

theresalech commented 4 years ago

Hi @E-SAITO-TMC, we have documented that this is priority for Toyota, and will include for Steering Committee review and vote when planning the contents for the Q4 Core release. This planning will take place in June. @kekapare, can you please advise on the results of your testing and/or if you are experiencing this issue when using Core 6.1? Thank you!

kekapare commented 4 years ago

@theresalech : Due to project deadlines and release scheduled, we did not include this fix in our product. Also, the issue was not reproducible. So, we could not work further on this issue.

Jack-Byrne commented 4 years ago

@kekapare Closing the issue. Please reopen if you are able to reproduce in the future.