New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 599059 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: Apr 2016
Cc:
EstimatedDays: ----
NextAction: ----
OS: Android
Pri: 1
Type: Bug



Sign in to add a comment

Clicking on notifications does not open chrome

Project Member Reported by miguelg@chromium.org, Mar 30 2016

Issue description

Version: ToT
OS: MNC (others too)

What steps will reproduce the problem?
(1) display a notification using tests.peter.sh/notification-generator
(2) swipe out chrome
(3) click on the notification

What is the expected output?

Chrome opens with tests.peter.sh/notification-generator

What do you see instead?
nothing happens


100% reproducible. Repeating the same steps but with chrome still running seems to work.

Logcat:

03-30 10:22:45.998  6960  6960 D StatusBar: Clicked on content of 0|com.google.android.apps.chrome|-1|NotificationUIManager;https://tests.peter.sh/;20|10093
03-30 10:22:46.001  6461  6622 D audio_hw_primary: out_set_parameters: enter: usecase(1: low-latency-playback) kvpairs: routing=2
03-30 10:22:46.002  6704  6730 W BroadcastQueue: Unable to launch app com.google.android.apps.chrome/10093 for broadcast Intent { act=org.chromium.chrome.browser.notifications.CLICK_NOTIFICATION dat=https://tests.peter.sh/... flg=0x10 cmp=com.google.android.apps.chrome/org.chromium.chrome.browser.notifications.NotificationService$Receiver (has extras) }: process is bad
03-30 10:22:46.015  6461  6621 D audio_hw_primary: select_devices: out_snd_device(2: speaker) in_snd_device(0: none)
03-30 10:22:46.015  6461  6621 I soundtrigger: audio_extn_sound_trigger_update_device_status: device 0x2 of type 0 for Event 1
03-30 10:22:46.015  6461  6621 D msm8974_platform: platform_send_audio_calibration: sending audio calibration for snd_device(2) acdb_id(101)
03-30 10:22:46.015  6461  6621 E ACDB-LOADER: ACDB get afe topology for acdb id = 101, err = -8
03-30 10:22:46.023  6461  6621 I soundtrigger: audio_extn_sound_trigger_update_device_status: device 0x42 of type 1 for Event 1
03-30 10:22:46.023  6461  6621 D sound_trigger_platform: platform_stdev_check_and_update_concurrency: concurrency active 0, tx 1, rx 0, concurrency session_allowed 0
03-30 10:22:46.023  6461  6621 D msm8974_platform: platform_send_audio_calibration: sending audio calibration for snd_device(66) acdb_id(102)
03-30 10:22:46.023  6461  6621 E ACDB-LOADER: Error: ACDB AudProc vol returned = -19
03-30 10:22:46.023  6461  6621 E ACDB-LOADER: ACDB get afe topology for acdb id = 102, err = -8
03-30 10:22:46.024  6461  6621 D audio_hw_primary: enable_snd_device: snd_device(66: vi-feedback)
03-30 10:22:46.024  6461  6621 D audio_hw_primary: enable_audio_route: apply and update mixer path: spkr-vi-record
03-30 10:22:46.025  6704  9766 W InputMethodManagerService: Window already focused, ignoring focus gain of: com.android.internal.view.IInputMethodClient$Stub$Proxy@fd434d2 attribute=null, token = android.os.BinderProxy@164d5ef
03-30 10:22:46.035  8450  8450 I HotwordWorker: voice unlock feature enabled = false, GMSCore version ok = true
03-30 10:22:46.046  8450  8450 I HotwordDataManager: Hotword configuration present: en-US en-US/hotword.data true
03-30 10:22:46.051  6461  6621 D msm8974_platform: platform_send_audio_calibration: sending audio calibration for snd_device(27) acdb_id(4)
03-30 10:22:46.051  6461  6621 E ACDB-LOADER: Error: ACDB AudProc vol returned = -19
03-30 10:22:46.051  6461  6621 E ACDB-LOADER: ACDB get afe topology for acdb id = 4, err = -8
03-30 10:22:46.051  6461  6621 E ACDB-LOADER: Error: ACDB AFE returned = -19
03-30 10:22:46.051  6461  6621 D audio_hw_primary: enable_audio_route: apply and update mixer path: low-latency-playback
03-30 10:22:46.064  8450  8450 I EventLoggerService: #cancelSendEvents
03-30 10:22:46.073  8450  8450 W LocationOracleImpl: Best location was null
03-30 10:22:46.094  7302  8465 W GCoreFlp: No location to return for getLastLocation()
03-30 10:22:46.098  8450 13281 I HotwordRecognitionRnr: Starting hotword detection.
03-30 10:22:46.100  8450 13282 I MicrophoneInputStream: mic_starting com.google.android.apps.gsa.speech.audio.u@5fd20c8
03-30 10:22:46.106  6461 13285 I AudioFlinger: AudioFlinger's thread 0xed740000 ready to run
03-30 10:22:46.118  6461  6660 I SoundTriggerHwService::Module: void android::SoundTriggerHwService::Module::onCallbackEvent(const android::sp<android::SoundTriggerHwService::CallbackEvent>&) mClient == 0
03-30 10:22:46.122  8450 13282 I MicrophoneInputStream: mic_started com.google.android.apps.gsa.speech.audio.u@5fd20c8
03-30 10:22:46.129  6461 13285 D audio_hw_primary: select_devices: out_snd_device(0: none) in_snd_device(61: voice-rec-mic)
03-30 10:22:46.129  6461 13285 I soundtrigger: audio_extn_sound_trigger_update_device_status: device 0x3d of type 1 for Event 1
03-30 10:22:46.129  6461 13285 D sound_trigger_platform: platform_stdev_check_and_update_concurrency: concurrency active 0, tx 2, rx 0, concurrency session_allowed 0
03-30 10:22:46.129  6461 13285 D msm8974_platform: platform_send_audio_calibration: sending audio calibration for snd_device(61) acdb_id(62)
03-30 10:22:46.130  6461 13285 E ACDB-LOADER: Error: ACDB AudProc vol returned = -19
03-30 10:22:46.130  6461 13285 E ACDB-LOADER: ACDB get afe topology for acdb id = 62, err = -8
03-30 10:22:46.130  6461 13285 E ACDB-LOADER: Error: ACDB AFE returned = -19
03-30 10:22:46.130  6461 13285 D audio_hw_primary: enable_snd_device: snd_device(61: voice-rec-mic)
03-30 10:22:46.136  6461 13285 D audio_hw_primary: enable_audio_route: apply and update mixer path: audio-record
03-30 10:22:46.140  7302  7751 W GCoreFlp: No location to return for getLastLocation()
03-30 10:22:46.156  8450  8450 E LocationReceiver: Received bad location: null
03-30 10:22:46.177  8450  8450 E LocationReceiver: Received bad location: null
03-30 10:22:46.180  8450  8450 I HotwordWorker: onReady
03-30 10:22:46.465  6960  6960 D PhoneStatusBar: disable: < expand icons* alerts system_info* back home recent clock search quick_settings >
03-30 10:22:46.864   394   394 I MSM-irqbalance: Decided to move IRQ65 from CPU3 to CPU2
03-30 10:22:47.263   478  6893 E fpc_tac : fpc_tac_send_cmd failed with retval: 4


 

Comment 1 by peter@chromium.org, Mar 30 2016

I got the following more useful stack trace. "process is bad" is an utterly unclear way of describing that the process has crashed before during launch so Android won't even attempt to start it (until it starts successfully due to another launch, e.g. normal browser launch).

--------- beginning of crash
03-30 14:55:56.585 31359 31380 E AndroidRuntime: FATAL EXCEPTION: AsyncTask #1
03-30 14:55:56.585 31359 31380 E AndroidRuntime: Process: org.chromium.chrome, PID: 31359
03-30 14:55:56.585 31359 31380 E AndroidRuntime: java.lang.RuntimeException: An error occurred while executing doInBackground()
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at android.os.AsyncTask$3.done(AsyncTask.java:318)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at java.util.concurrent.FutureTask.finishCompletion(FutureTask.java:354)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at java.util.concurrent.FutureTask.setException(FutureTask.java:223)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at java.util.concurrent.FutureTask.run(FutureTask.java:242)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at java.lang.Thread.run(Thread.java:803)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: Caused by: java.lang.ExceptionInInitializerError
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at org.chromium.base.PathUtils$Holder.access$200(PathUtils.java:54)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at org.chromium.base.PathUtils.getDirectoryPath(PathUtils.java:141)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at org.chromium.base.PathUtils.getDataDirectory(PathUtils.java:150)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at org.chromium.base.ResourceExtractor.getAppDataDir(ResourceExtractor.java:348)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at org.chromium.base.ResourceExtractor.getOutputDir(ResourceExtractor.java:352)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at org.chromium.base.ResourceExtractor.access$000(ResourceExtractor.java:34)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at org.chromium.base.ResourceExtractor$ExtractTask.doInBackgroundImpl(ResourceExtractor.java:94)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at org.chromium.base.ResourceExtractor$ExtractTask.doInBackground(ResourceExtractor.java:161)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at org.chromium.base.ResourceExtractor$ExtractTask.doInBackground(ResourceExtractor.java:58)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at android.os.AsyncTask$2.call(AsyncTask.java:304)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at java.util.concurrent.FutureTask.run(FutureTask.java:237)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	... 3 more
03-30 14:55:56.585 31359 31380 E AndroidRuntime: Caused by: java.lang.NullPointerException: Attempt to invoke virtual method 'boolean android.os.AsyncTask.cancel(boolean)' on a null object reference
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at org.chromium.base.PathUtils.getOrComputeDirectoryPaths(PathUtils.java:69)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at org.chromium.base.PathUtils.access$000(PathUtils.java:25)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	at org.chromium.base.PathUtils$Holder.<clinit>(PathUtils.java:55)
03-30 14:55:56.585 31359 31380 E AndroidRuntime: 	... 14 more

Comment 2 by peter@chromium.org, Mar 30 2016

This class has a whole bunch of asserts in place, but these don't actually do anything. PathUtils.setPrivateDataDirectorySuffix() has not been called yet from wherever we come from.

Comment 3 by peter@chromium.org, Mar 30 2016

So I found a few solutions, but it uncovered something else that's far from nice. Consider the following time:

15:47:17.243 31246 31246 I NotificationService: Received a notification intent in the NotificationService's receiver.
15:47:18.138 31246 31246 I cr_LibraryLoader: Time to load native libraries: 850 ms (timestamps 6096-6946)
15:47:18.138 31246 31246 I cr_LibraryLoader: Expected native library version number "51.0.2695.0", actual native library version number "51.0.2695.0"
15:47:18.587 31246 31279 I chromium: [INFO:notification_event_dispatcher_impl.cc(104)] Trying to dispatch notification for SW with status: 0
15:47:18.990 31284 31284 I cr_ChildProcessService: Creating new ChildProcessService pid=31284
15:47:19.182 31307 31307 I cr_ChildProcessService: Creating new ChildProcessService pid=31307
15:47:20.828 31284 31323 I cr_LibraryLoader: Time to load native libraries: 1810 ms (timestamps 7826-9636)
15:47:21.031 31307 31324 I cr_LibraryLoader: Time to load native libraries: 1779 ms (timestamps 8052-9831)
15:47:21.284 31246 31279 I chromium: [INFO:notification_event_dispatcher_impl.cc(53)] The notification event has finished: 0
15:47:21.308   934 30620 I ActivityManager: START u0 {act=android.intent.action.VIEW dat=https://tests.peter.sh/... flg=0x10000000 pkg=org.chromium.chrome cmp=org.chromium.chrome/.browser.document.ChromeLauncherActivity (has extras)} from uid 10123 on display 0
15:47:21.837 31246 31246 D StrictMode: StrictMode policy violation; ~duration=308 ms: android.os.StrictMode$StrictModeDiskReadViolation: policy=17891359 violation=2
15:47:21.837 31246 31246 D StrictMode: StrictMode policy violation; ~duration=304 ms: android.os.StrictMode$StrictModeDiskReadViolation: policy=17891359 violation=2
15:47:22.022 31336 31336 I cr_ChildProcessService: Creating new ChildProcessService pid=31336
15:47:23.070 31336 31356 I cr_LibraryLoader: Time to load native libraries: 879 ms (timestamps 999-1878)

Summarized:
  - It takes ~850ms to load the native library on click.
  - We then create two child processes.
    - (1) for the Service Worker. Takes 1810ms to load the native libraries.
    - (2) seems to be unused? Takes 1779ms to load the native libraries.
  - The `notificationclick` event is done dispatching after four seconds. An intent has been fired to open a window.
  - Two strict mode violations occur, each taking ~300ms. Related to shared preferences.
  - Another child process has been created. Takes 879ms to load the native libraries.
  - Six seconds after clicking on the notification, the window has been opened.

This is terribly long.

Comment 4 by peter@chromium.org, Mar 30 2016

Status: Started (was: Available)
CL here, will add a test in a moment:

  https://codereview.chromium.org/1847573003

I'll split out the problems from comment #3 in separate issues.
Project Member

Comment 5 by bugdroid1@chromium.org, Mar 31 2016

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/3c2d44918c2a4b5a6f829f70ca4528f23bb8c9be

commit 3c2d44918c2a4b5a6f829f70ca4528f23bb8c9be
Author: peter <peter@chromium.org>
Date: Thu Mar 31 15:57:55 2016

Use the ChromeBrowserInitializer on incoming notification intents

This removes the need for this entry point to set up command line flags
and the PathUtils directory prefix ourselves.

BUG= 599059 

Review URL: https://codereview.chromium.org/1847573003

Cr-Commit-Position: refs/heads/master@{#384292}

[modify] https://crrev.com/3c2d44918c2a4b5a6f829f70ca4528f23bb8c9be/chrome/android/java/src/org/chromium/chrome/browser/notifications/NotificationService.java
[modify] https://crrev.com/3c2d44918c2a4b5a6f829f70ca4528f23bb8c9be/chrome/android/javatests/src/org/chromium/chrome/browser/notifications/NotificationUIManagerIntentTest.java

Comment 6 by peter@chromium.org, Apr 1 2016

Status: Fixed (was: Started)

Sign in to add a comment