Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Android auto doesn't start after car turns off and turns on again #61

Closed
ignabel opened this issue Mar 4, 2017 · 4 comments · Fixed by #92
Closed

Android auto doesn't start after car turns off and turns on again #61

ignabel opened this issue Mar 4, 2017 · 4 comments · Fixed by #92
Labels

Comments

@ignabel
Copy link

ignabel commented Mar 4, 2017

I'm running latest build 5ef71ea on my 2016 3 with v55.

If AA isrunning and I turn off the car, unplug my phone, plug it in again and after a few secs turn the car on again, AA doesn't start automatically or manually. If I try to open AA manually on the car I get an error message:

_StartContextReady: Can't connect to headunit process

Only solution is to restart the headunit with back-nav-mute. I think this only happens if the "stop" is short so that the headunit doesn't go to deep sleep.

Another way to get to that error message and probably related:
If I turn on the car on accessory mode (one start button press) with my phone plugged in, AA launches OK, if I then start the car while AA is running, AA freezes and after hitting home and trying to re-launch it in the car I get the same error message "_StartContextReady: Can't connect to headunit process"

Image of error message: https://goo.gl/photos/YAU1SBwrmvf1Dwog7

@lmagder lmagder added the bug label Mar 5, 2017
@lmagder
Copy link
Collaborator

lmagder commented Mar 5, 2017

My hunch here is what's happening is that the headunit process is crashing and then isn't restarted until the next true boot. Unfortunately the code which displays the log is broken, but if you can repro and copy off the /tmp/mnt/data/headunit.log file and post it might help.

A hacky workaround would be to modify the headunit_wrapper script to re-launch the process if it crashes, but ideally the code should be fixed to handle the events it's getting from the car correctly.

@ignabel
Copy link
Author

ignabel commented Mar 5, 2017

Below is headunit.log. It's the entire file but you'll see a line of asterisks that I added before starting reproducing the error (turning on the car, AA runs OK, turn off the car and ON again to see the error).

The missing plugins warnings and errors at the beginning of the log is something I also saw in the install log.

Hope it helps. Let me know if you need anything else.

uname:
 sysname: Linux
 release: 3.0.35
 version: #1 SMP PREEMPT Sun Mar 15 10:12:10 IST 2015
 machine: armv7l
libprotoversion: 2.6.1
libusb_get_version:
 version: 1.0.9.0
 rc: 
 describe: 
openssl version: OpenSSL 1.0.2h  3 May 2016 (0x1000208f)

(gst-plugin-scanner:3230): GStreamer-WARNING **: Failed to load plugin '/usr/lib/gstreamer-0.10/libmfw_gst_mpeg2dec.so': lib_mpeg2_dec_arm11_elinux.so.2.2.0: cannot open shared object file: No such file or directory

(gst-plugin-scanner:3230): GStreamer-WARNING **: Failed to load plugin '/usr/lib/gstreamer-0.10/libmfw_gst_h264dec.so': lib_H264_dec_arm11_elinux.so.2.6.1: cannot open shared object file: No such file or directory

(gst-plugin-scanner:3230): GStreamer-CRITICAL **: gst_pad_template_new: assertion `caps != NULL' failed

(gst-plugin-scanner:3230): GStreamer-CRITICAL **: gst_element_class_add_pad_template: assertion `GST_IS_PAD_TEMPLATE (templ)' failed

(gst-plugin-scanner:3230): GStreamer-WARNING **: Failed to load plugin '/usr/lib/gstreamer-0.10/libmfw_gst_mpeg4aspdec.so': lib_MPEG4ASP_dec_arm11_elinux.so.1.2.1: cannot open shared object file: No such file or directory
�[1;34mMAX resolution 800x480
�[0mLooping
DBus::Glib::BusDispatcher attached
Making debug connections
snd_asoundlib_version: 1.0.24.1
dumpState({"pretty":false,"svc":"SRCS"})
{"HMI":{},"APP":["22.VR.SYSVR..NotPlaying","21.Media.AHA..NotPlaying","20.Media.Pandora..NotPlaying","19.Media.Stitcher..NotPlaying","18.Media.TV..NotPlaying","9.Media.LM..NotPlaying","1.Media.AUX..NotPlaying","15.MedAlert.BTHFALERT..NotPlaying","3.Media.DAB..NotPlaying","2.Media.CD..NotPlaying","5.Media.AM..NotPlaying","4.Media.XM..NotPlaying","7.LowAlert.TA..NotPlaying","6.Media.FM.gained.playing","14.Telephony.BTHF..NotPlaying","8.Media.HAR..NotPlaying","16.Media.USB..NotPlaying","17.Media.DVD..NotPlaying","13.Media.BTMUSIC..NotPlaying","12.InfoUser.RINGTONEVOL..NotPlaying","11.InfoMix.NAVIVOL..NotPlaying","10.InfoUser.BTHFVOL..NotPlaying"]}
Found stream SYSVR session id 22
Found stream AHA session id 21
Found stream Pandora session id 20
Found stream Stitcher session id 19
Found stream TV session id 18
Found stream LM session id 9
Found stream AUX session id 1
Found stream BTHFALERT session id 15
Found stream DAB session id 3
Found stream CD session id 2
Found stream AM session id 5
Found stream XM session id 4
Found stream TA session id 7
Found stream FM session id 6
Found stream BTHF session id 14
Found stream HAR session id 8
Found stream USB session id 16
Found stream DVD session id 17
Found stream BTMUSIC session id 13
Found stream RINGTONEVOL session id 12
Found stream NAVIVOL session id 11
Found stream BTHFVOL session id 10
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x1d6b : 0x0002
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x1d6b : 0x0002
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x0424 : 0x2640
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x0424 : 0x4040
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:437: Start : Nothing found, waiting
W: /mnt/e/gittest/headunit/hu/hu_uti.cpp:371: wait_for_device_connection : udev device removeed | node:/dev/bus/usb/002/003, subsystem:usb, devtype:usb_device

W: /mnt/e/gittest/headunit/hu/hu_uti.cpp:371: wait_for_device_connection : udev device removeed | node:/dev/bus/usb/002/002, subsystem:usb, devtype:usb_device

W: /mnt/e/gittest/headunit/hu/hu_uti.cpp:371: wait_for_device_connection : udev device added | node:/dev/bus/usb/002/004, subsystem:usb, devtype:usb_device

W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x1d6b : 0x0002
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x1d6b : 0x0002
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x0424 : 0x2640
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:437: Start : Nothing found, waiting
W: /mnt/e/gittest/headunit/hu/hu_uti.cpp:371: wait_for_device_connection : udev device added | node:/dev/bus/usb/002/005, subsystem:usb, devtype:usb_device

W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x1d6b : 0x0002
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x1d6b : 0x0002
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x0424 : 0x2640
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x0424 : 0x4040
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:437: Start : Nothing found, waiting
**********************************************************************************************************
W: /mnt/e/gittest/headunit/hu/hu_uti.cpp:371: wait_for_device_connection : udev device added | node:/dev/bus/usb/002/006, subsystem:usb, devtype:usb_device

W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x1d6b : 0x0002
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x1d6b : 0x0002
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x0424 : 0x2640
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x0424 : 0x4040
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:377: Start : Opening device 0x04e8 : 0x6860
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:394: Start : Device 0x04e8 : 0x6860 responded with protocol ver 2
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:428: Start : Wating for the device to reconnect
W: /mnt/e/gittest/headunit/hu/hu_uti.cpp:371: wait_for_device_connection : udev device removeed | node:/dev/bus/usb/002/006, subsystem:usb, devtype:usb_device

W: /mnt/e/gittest/headunit/hu/hu_uti.cpp:371: wait_for_device_connection : udev device added | node:/dev/bus/usb/002/007, subsystem:usb, devtype:usb_device

W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:449: Start : Found OAP Device
E: /mnt/e/gittest/headunit/hu/hu_usb.cpp:453: Start : Error libusb_claim_interface usb_err: -5 (Entity not found)
E: /mnt/e/gittest/headunit/hu/hu_usb.cpp:191: Stop : Done libusb_release_interface usb_err: -5 (Entity not found)
E: main.cpp:166: main : Something bad happened
DBus::Glib::BusDispatcher attached
Making debug connections
snd_asoundlib_version: 1.0.24.1
dumpState({"pretty":false,"svc":"SRCS"})
{"HMI":{},"APP":["26.InfoUser.SMS..NotPlaying","25.HighAlert.BTECAALERT..NotPlaying","24.MP911.BTECA..NotPlaying","23.InfoUser.PHONEBOOK..NotPlaying","22.VR.SYSVR..NotPlaying","21.Media.AHA..NotPlaying","20.Media.Pandora..NotPlaying","19.Media.Stitcher..NotPlaying","18.Media.TV..NotPlaying","9.Media.LM..NotPlaying","1.Media.AUX..NotPlaying","15.MedAlert.BTHFALERT..NotPlaying","3.Media.DAB..NotPlaying","2.Media.CD..NotPlaying","5.Media.AM..NotPlaying","4.Media.XM..NotPlaying","7.LowAlert.TA..NotPlaying","6.Media.FM.gained.playing","14.Telephony.BTHF..NotPlaying","8.Media.HAR..NotPlaying","16.Media.USB..NotPlaying","17.Media.DVD..NotPlaying","13.Media.BTMUSIC..NotPlaying","12.InfoUser.RINGTONEVOL..NotPlaying","11.InfoMix.NAVIVOL..NotPlaying","10.InfoUser.BTHFVOL..NotPlaying"]}
Found stream SMS session id 26
Found stream BTECAALERT session id 25
Found stream BTECA session id 24
Found stream PHONEBOOK session id 23
Found stream SYSVR session id 22
Found stream AHA session id 21
Found stream Pandora session id 20
Found stream Stitcher session id 19
Found stream TV session id 18
Found stream LM session id 9
Found stream AUX session id 1
Found stream BTHFALERT session id 15
Found stream DAB session id 3
Found stream CD session id 2
Found stream AM session id 5
Found stream XM session id 4
Found stream TA session id 7
Found stream FM session id 6
Found stream BTHF session id 14
Found stream HAR session id 8
Found stream USB session id 16
Found stream DVD session id 17
Found stream BTMUSIC session id 13
Found stream RINGTONEVOL session id 12
Found stream NAVIVOL session id 11
Found stream BTHFVOL session id 10
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:449: Start : Found OAP Device
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:457: Start : OK libusb_claim_interface usb_err: 0 (Success)
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:471: Start : Done get_config_descriptor config: 0x65c378  num_int: 2
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:496: Start : iusb_ep_in: 0x81
W: /mnt/e/gittest/headunit/hu/hu_usb.cpp:503: Start : iusb_ep_out: 0x02
W: /mnt/e/gittest/headunit/hu/hu_ssl.cpp:210: hu_ssl_begin_handshake : SSL_do_handshake() ret: -1
W: /mnt/e/gittest/headunit/hu/hu_ssl.cpp:66: send_ssl_handshake_packet : BIO_read() HS client req ret: 307
W: /mnt/e/gittest/headunit/hu/hu_ssl.cpp:233: hu_handle_SSLHandshake : BIO_write() server rsp ret: 2310
W: /mnt/e/gittest/headunit/hu/hu_ssl.cpp:236: hu_handle_SSLHandshake : SSL_do_handshake() ret: -1
W: /mnt/e/gittest/headunit/hu/hu_ssl.cpp:66: send_ssl_handshake_packet : BIO_read() HS client req ret: 1224
W: /mnt/e/gittest/headunit/hu/hu_ssl.cpp:233: hu_handle_SSLHandshake : BIO_write() server rsp ret: 51
W: /mnt/e/gittest/headunit/hu/hu_ssl.cpp:236: hu_handle_SSLHandshake : SSL_do_handshake() ret: 1
W: /mnt/e/gittest/headunit/hu/hu_ssl.cpp:262: hu_handle_SSLHandshake :   SET: iaap_state: 2 (hu_STATE_STARTED)
W: /mnt/e/gittest/headunit/hu/hu_aap.cpp:1124: hu_aap_start : Starting HU thread
Starting Android Auto...
GPS thread started...Nightmode service connection established.
Bluetooth MAC: FC:35:E6:7C:1E:A2
W: /mnt/e/gittest/headunit/hu/hu_aap.cpp:546: hu_handle_ServiceDiscoveryRequest : Found BT address FC:35:E6:7C:1E:A2. Exposing Bluetooth service
W: /mnt/e/gittest/headunit/hu/hu_aap.cpp:631: hu_handle_AudioFocusRequest : AudioFocusRequest Focus Request CTR: 4
�[1;32mMFW_GST_ISINK_PLUGIN 3.0.5 build on Jun 10 2015 16:30:48.
�[0m�[1;32mvpudec versions :)
�[0m�[1;32m	plugin: 3.0.5
�[0m�[1;32m	wrapper: 1.0.28(VPUWRAPPER_ARM_LINUX Build on Jun 10 2015 16:26:09)
�[0m�[1;32m	vpulib: 5.4.10
�[0m�[1;32m	firmware: 2.1.8.34588
�[0mE: /mnt/e/gittest/headunit/hu/hu_aap.cpp:922: iaap_msg_process : Unknown chan: 8
hwbuf allocator zone(577536) created
�[1;34mVS0 created. in fmt[NV12] win(0,0-800,480:800x480) out win(0,-20-800,500:800x520)
�[0m�[1;34mset deinterlace mode 0
�[0mE: gps/mzd_gps.cpp:64: process_gps : GPS parse error: GPS Data Bad Format [$GPGSV] :: Checksum is invalid!.
W: /mnt/e/gittest/headunit/hu/hu_aap.cpp:631: hu_handle_AudioFocusRequest : AudioFocusRequest Focus Request CTR: 1
requestAudioFocus({"sessionId":16})
{}
AudioManagerClient::Notify signalName=audioFocusChangeEvent payload={"streamName":"FM","streamModeName":"FM","newFocus":"lost","destination":"Cabin","focusType":"permanent","streamType":"Media"}
Found audio sessionId 6 for stream FM
AudioManagerClient::Notify signalName=audioFocusChangeEvent payload={"streamName":"USB","streamModeName":"USB","newFocus":"gained","destination":"Cabin","focusType":"permanent","streamType":"Media"}
Found audio sessionId 16 for stream USB
E: /mnt/e/gittest/headunit/hu/hu_usb.cpp:103: Write :   Failed: libusb_submit_transfer: -4 (No such device (it may have been disconnected))
E: /mnt/e/gittest/headunit/hu/hu_aap.cpp:144: hu_aap_tra_send : Error ihu_tra_send() error so stop Transport & AAP  ret: -1  len: 39
E: /mnt/e/gittest/headunit/hu/hu_usb.cpp:103: Write :   Failed: libusb_submit_transfer: -4 (No such device (it may have been disconnected))
E: /mnt/e/gittest/headunit/hu/hu_aap.cpp:144: hu_aap_tra_send : Error ihu_tra_send() error so stop Transport & AAP  ret: -1  len: 37
E: /mnt/e/gittest/headunit/hu/hu_usb.cpp:103: Write :   Failed: libusb_submit_transfer: -4 (No such device (it may have been disconnected))
E: /mnt/e/gittest/headunit/hu/hu_aap.cpp:144: hu_aap_tra_send : Error ihu_tra_send() error so stop Transport & AAP  ret: -1  len: 37
E: /mnt/e/gittest/headunit/hu/hu_usb.cpp:103: Write :   Failed: libusb_submit_transfer: -4 (No such device (it may have been disconnected))
E: /mnt/e/gittest/headunit/hu/hu_aap.cpp:144: hu_aap_tra_send : Error ihu_tra_send() error so stop Transport & AAP  ret: -1  len: 37
E: /mnt/e/gittest/headunit/hu/hu_usb.cpp:103: Write :   Failed: libusb_submit_transfer: -4 (No such device (it may have been disconnected))
E: /mnt/e/gittest/headunit/hu/hu_aap.cpp:144: hu_aap_tra_send : Error ihu_tra_send() error so stop Transport & AAP  ret: -1  len: 37
E: /mnt/e/gittest/headunit/hu/hu_usb.cpp:103: Write :   Failed: libusb_submit_transfer: -4 (No such device (it may have been disconnected))
E: /mnt/e/gittest/headunit/hu/hu_aap.cpp:144: hu_aap_tra_send : Error ihu_tra_send() error so stop Transport & AAP  ret: -1  len: 37

@lmagder
Copy link
Collaborator

lmagder commented Mar 5, 2017

Thanks! So just for confirm: This log (past the ****s) is from you connecting the phone when the car UI is on, but the engine is not started? Then you start the engine and AA freezes? (probably where all the usb errors are at the bottom).

It seems like we don't handle USB errors other than disconnects very well and the code could be deadlocking. Perhaps the USB connections are reset when the engine starts? I've noticed the audio cuts out even with the stock SW.

@ignabel
Copy link
Author

ignabel commented Mar 5, 2017

So there are two ways to get to the error.

A) Turn on car, plug phone, AA starts, turn car off and back on, plug phone, AA doesn't launch and error appears if you try to launch it manually.

B) Start the car on accessory mode, plug phone, AA starts, start car, AA freezes and if you try to reconnect the phone, AA doesn't launch and error appears if you try to launch it manually

The log is from A). Here's exactly what I did step by step:

  1. Turned on the car to accessory mode and connected it to my wifi
  2. Connected to the car though FTP and downloaded headunit.log for the first time and that log ended right above the ****s
  3. Went back to the car and plugged my phone, AA launched and worked fine.
  4. Turned off the car (I was in accessory mode)
  5. Unplugged the phone
  6. Turned accessory mode back on
  7. Plugged the phone, waited and nothing happened on the car
  8. Tried to launch AA manually on the car and I see the error _StartContextReady: Can't connect to headunit process
  9. Went back to my computer and downloaded headunit.log again and everything after the ***s was new.

I really never started the engine in this particular test as it seems to not matter at all as I just went back to the car and did the same steps 1 to 7, got the error, and then turned on the car and the error was still there. I also tried to unplug and re-plug the phone and a few other things such as shutting down the engine and turning it back on, without success.

I feels that once I get the error the only way to get AA running again is to reboot the headunit or turn off the car and wait 30 mins or whatever the car takes to get the headunit to sleep.

Trevelopment added a commit to Trevelopment/headunit that referenced this issue Nov 4, 2017
The audio stream is a preference but the consensus seems to be that it is better when set to default.
Removing the vehicle GPS does not seem to effect the navigation at all and greatly reduces audio stuttering and possibly fixes gartnera#51, gartnera#61, & gartnera#87
Trevelopment added a commit to Trevelopment/headunit that referenced this issue Nov 4, 2017
The audio stream is a preference but the consensus seems to be that it is better when set to default.
Removing the vehicle GPS does not seem to effect the navigation at all and greatly reduces audio stuttering and possibly fixes gartnera#51, gartnera#61, & gartnera#87
Trevelopment added a commit to Trevelopment/headunit that referenced this issue Nov 4, 2017
The audio stream channel is a personal preference but the consensus seems to be that it is better when set to default.
Removing the vehicle GPS does not seem to effect the navigation at all and greatly reduces audio stuttering and possibly fixes gartnera#51, gartnera#61, & gartnera#87
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants