search

mozilla-mobile / firefox-tv

Firefox for Amazon's Fire TV
https://blog.mozilla.org/blog/2017/12/20/firefox-is-now-on-amazon-fire-tv-happy-holiday-watching/
Mozilla Public License 2.0
257 stars 111 forks source link

[FxA] The tabs are not received on the FFTV (unknown STR; Java does not receive tabs) #2833

Open abodea opened 5 years ago

abodea commented 5 years ago

See https://github.com/mozilla-mobile/firefox-tv/issues/2867 where tabs are not received after clearing data. In that issue, Java appears to receive the tab but drop it on the floor. In this issue, Java never receives the tab. I was only able to determine this via the debugger where AbstractAmazonPushService.onMessage was not called.

Steps to reproduce

  1. Launch FFTV.
  2. Activate Send Tab using adb shell am start -n org.mozilla.tv.firefox/org.mozilla.tv.firefox.MainActivity -a android.intent.action.MAIN --esa qaActiveExperiments SendTab-2511:B command. This is enabled by default now
  3. Sign in to FxA on FFTV
  4. From another device send any tabs.

    Expected behavior

    The tabs are received on the FFTV.

    Actual behavior

    The tabs are not received on the FFTV.

    Device information

    • Fire TV device: Fire TV Stick 4k
    • Latest affected Firefox version: FF for Fire TV 4.5-LAT2
    • Earliest affected Firefox version: FF for Fire TV 4.5-LAT2
    • Turbo Mode: On and Off log.txt
abodea commented 5 years ago

When I tried to send a tab multiple times and I clicked on the Request desktop site the FFTV froze. log2.txt


    PID: 25904
    Reason: Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it.  Outbound queue length: 0.  Wait queue length: 1.)
    Load: 5.37 / 5.75 / 5.7
    CPU usage from 259891ms to 0ms ago (2019-09-13 13:04:36.423 to 2019-09-13 13:08:56.314):
      67% 25904/org.mozilla.tv.firefox: 56% user + 11% kernel / faults: 120028 minor 1183 major
      13% 26093/com.amazon.webview.chromium:sandboxed_process1: 12% user + 1.3% kernel / faults: 46037 minor 145 major
      11% 243/surfaceflinger: 5.7% user + 5.7% kernel / faults: 1141 minor 19 major
      6.1% 286/audioserver: 4% user + 2% kernel / faults: 883 minor 26 major
      4.5% 608/system_server: 3% user + 1.5% kernel / faults: 15069 minor 518 major
      1.6% 136/disp_osd2_irq_k: 0% user + 1.6% kernel
      1.4% 1301/com.amazon.tv.launcher: 1.1% user + 0.3% kernel / faults: 28283 minor 765 major
      1.3% 135/disp_osd1_irq_k: 0% user + 1.3% kernel
      1.2% 134/disp_osd2_confi: 0% user + 1.2% kernel
      1.2% 2650/com.amazon.discoveryservice.core.android: 1% user + 0.1% kernel / faults: 9985 minor 3 major
      0.7% 56/kswapd0: 0% user + 0.7% kernel
      0.6% 26/ksmd: 0% user + 0.6% kernel
      0.6% 127/pvr_defer_free: 0% user + 0.6% kernel
      0.6% 24530/kworker/u8:6: 0% user + 0.6% kernel
      0.4% 14962/kworker/u8:5: 0% user + 0.4% kernel
      0.3% 24498/kworker/u8:0: 0% user + 0.3% kernel
      0.4% 26515/kworker/u8:1: 0% user + 0.4% kernel
      0.4% 869/hif_thread: 0% user + 0.4% kernel
      0.3% 1199/com.amazon.tcomm: 0.2% user + 0% kernel / faults: 9058 minor 152 major
      0.3% 23496/kworker/u8:3: 0% user + 0.3% kernel
      0.3% 196/logd: 0.2% user + 0.1% kernel / faults: 1048 minor 56 major
      0.3% 218/ksdioirqd/mmc1: 0% user + 0.3% kernel
      0.3% 99/hdmi_timer_kthr: 0% user + 0.3% kernel
      0.2% 1628/com.amazon.kso.blackbird:BlackbirdServiceProcess: 0.2% user + 0% kernel / faults: 9676 minor 216 major
      0.2% 258/adbd: 0.1% user + 0.1% kernel / faults: 3535 minor
      0.2% 871/rx_thread: 0% user + 0.2% kernel
      0.2% 7/rcu_preempt: 0% user + 0.2% kernel
      0.2% 152/mmcqd/0: 0% user + 0.2% kernel
      0.2% 26171/com.amazon.avod: 0.2% user + 0% kernel / faults: 9366 minor 774 major
      0.2% 863/main_thread: 0% user + 0.2% kernel
      0.1% 1253/com.amazon.client.metrics: 0.1% user + 0% kernel / faults: 5921 minor 151 major
      0.1% 1835/com.amazon.venezia: 0.1% user + 0% kernel / faults: 15168 minor 799 major
      0.1% 24994/kworker/u8:2: 0% user + 0.1% kernel
      0.1% 25537/com.amazon.device.messaging: 0.1% user + 0% kernel / faults: 2011 minor 18 major
      0.1% 25135/kworker/2:0: 0% user + 0.1% kernel
      0.1% 3044/com.amazon.whisperlink.core.android: 0.1% user + 0% kernel / faults: 2649 minor 3 major
      0% 281/media.codec: 0% user + 0% kernel / faults: 5598 minor 84 major
      0.1% 742/com.android.bluetooth: 0% user + 0% kernel / faults: 2052 minor 287 major
      0.1% 1174/com.amazon.vizzini: 0% user + 0% kernel / faults: 4045 minor 97 major
      0.1% 4510/com.netflix.ninja: 0% user + 0% kernel / faults: 5707 minor 6 major
      0% 100/cec_timer_kthre: 0% user + 0% kernel
      0% 33/cfinteractive: 0% user + 0% kernel
      0% 25097/logcat: 0% user + 0% kernel / faults: 99 minor 4 major
      0% 139/video_disp0: 0% user + 0% kernel
      0% 25433/kworker/0:0: 0% user + 0% kernel
      0% 26721/kworker/3:0: 0% user + 0% kernel
      0% 141/disp_dovi_vsync: 0% user + 0% kernel
      0% 1468/com.amazon.tv.ime: 0% user + 0% kernel / faults: 2212 minor 9 major
      0% 140/video_disp1: 0% user + 0% kernel
      0% 298/sh: 0% user + 0% kernel / faults: 4279 minor
      0% 1183/com.amazon.imp: 0% user + 0% kernel / faults: 4144 minor 19 major
      0% 25208/kworker/1:1: 0% user + 0% kernel
      0% 22905/com.amazon.ceviche: 0% user + 0% kernel / faults: 4510 minor 41 major
      0% 26487/com.amazon.bueller.photos: 0% user + 0% kernel / faults: 871 minor 2 major
      0% 16/ksoftirqd/2: 0% user + 0% kernel
      0% 86/hwrng: 0% user + 0% kernel
      0% 118/irq/109-sdio-ei: 0% user + 0% kernel
      0% 1213/com.amazon.tv.devicec
2019-09-13 13:09:00.508 608-617/? I/art: Background partial concurrent mark sweep GC freed 30735(2MB) AllocSpace objects, 13(3MB) LOS objects, 16% free, 19MB/23MB, paused 3.296ms total 131.391ms
2019-09-13 13:09:00.517 608-27170/? I/CrashReporterActivityManagerCallback: ANR addErrorToDropBox inserted hashcode=160162da635aa1e800d866ebb910293ffb254632.
2019-09-13 13:09:00.522 608-27170/? E/SELinux: avc:  denied  { log_internal_metric } for  scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:system_server:s0 tclass=amazon_policies permissive=0
2019-09-13 13:09:00.558 608-621/? E/SELinux: avc:  denied  { log_internal_metric } for  scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:system_server:s0 tclass=amazon_policies permissive=0
2019-09-13 13:09:00.560 608-621/? I/CrashReporterActivityManagerCallback: ANR trace inserted line:
    TraceHashCode: 160162da635aa1e800d866ebb910293ffb254632    
    into file /data/anr/traces_org.mozilla.tv.firefox.txt
2019-09-13 13:09:00.562 608-620/? I/CrashDescriptorUtil: addErrorToCommonLog trace inserted line :160162da635aa1e800d866ebb910293ffb254632into file /data/anr/traces_commonlog.txt
2019-09-13 13:09:00.568 608-621/? I/CrashReporterActivityManagerCallback: appNotResponding: finished changing trace file
2019-09-13 13:09:00.569 608-622/? W/ActivityManager:   Force finishing activity org.mozilla.tv.firefox/.MainActivity
2019-09-13 13:09:00.572 243-1483/? D/qdqservice: QService::getSupportedResolutions: u4res_ntsc=0xb, u4res_pal=0x2c00, u4res_4k=0x0, u4res=0x2c0b
2019-09-13 13:09:00.572 243-1483/? I/qdqservice: QService::getAutoMode
2019-09-13 13:09:00.573 243-1483/? D/qdqservice: QService::getAutoMode: hdmiMode 13
2019-09-13 13:09:00.573 243-1483/? D/qdqservice: QService::convertOutputResCode: Found match: returning vic=16
2019-09-13 13:09:00.573 243-1483/? D/qdqservice: QService::getAutoMode: vicMode 16
2019-09-13 13:09:00.577 608-622/? I/ActivityManager: Killing 25904:org.mozilla.tv.firefox/u0a170 (adj 0): user request after error
2019-09-13 13:09:00.745 608-671/? W/InputDispatcher: channel '23a63f6 PopupWindow:41bf168 (server)' ~ Consumer closed input channel or an error occurred.  events=0x9
2019-09-13 13:09:00.745 608-22002/? I/WindowManager: WIN DEATH: Window{23a63f6 u0 PopupWindow:41bf168}
2019-09-13 13:09:00.745 608-671/? E/InputDispatcher: channel '23a63f6 PopupWindow:41bf168 (server)' ~ Channel is unrecoverably broken and will be disposed!
2019-09-13 13:09:00.745 608-671/? W/InputDispatcher: channel '2ef1e7e org.mozilla.tv.firefox/org.mozilla.tv.firefox.MainActivity (server)' ~ Consumer closed input channel or an error occurred.  events=0x9
2019-09-13 13:09:00.745 608-671/? E/InputDispatcher: channel '2ef1e7e org.mozilla.tv.firefox/org.mozilla.tv.firefox.MainActivity (server)' ~ Channel is unrecoverably broken and will be disposed!
2019-09-13 13:09:00.745 608-6872/? D/ConnectivityService: ConnectivityService NetworkRequestInfo binderDied(NetworkRequest [ LISTEN id=80, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&FOREGROUND] ], android.os.BinderProxy@8651801)
2019-09-13 13:09:00.745 608-21433/? D/GraphicsStats: Buffer count: 5
2019-09-13 13:09:00.745 608-21433/? D/ConnectivityService: ConnectivityService NetworkRequestInfo binderDied(NetworkRequest [ LISTEN id=81, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&FOREGROUND] ], android.os.BinderProxy@221b6a6)
2019-09-13 13:09:00.747 742-912/? V/Avrcp: MediaController session destroyed
2019-09-13 13:09:00.747 1174-1519/? D/Vizzini:MediaSessionLib.MediaSessionControllerStateMgr: Session destroyed org.mozilla.tv.firefox
2019-09-13 13:09:00.748 742-912/? V/Avrcp: Active sessions changed, 1 sessions
2019-09-13 13:09:00.748 742-912/? V/Avrcp: Updating media controller to android.media.session.MediaController@5f872e3
2019-09-13 13:09:00.749 1174-1519/? D/Vizzini:MediaSessionLib.MediaSessionCommandQueue: Active Sessions changed: 1
2019-09-13 13:09:00.749 608-21433/? E/SELinux: avc:  denied  { log_internal_metric } for  scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:system_server:s0 tclass=amazon_policies permissive=0
2019-09-13 13:09:00.750 608-21433/? D/ActivityManager: cleanUpApplicationRecord -- 25904
2019-09-13 13:09:00.750 742-912/? V/Avrcp: Updated [MediaAttributes: none] but no change!
2019-09-13 13:09:00.750 608-692/? E/ConnectivityService: RemoteException caught trying to send a callback msg for NetworkRequest [ LISTEN id=80, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&FOREGROUND] ]
2019-09-13 13:09:00.751 1174-1519/? D/Vizzini:MediaSessionLib.MediaSessionControllerStateMgr: org.mozilla.tv.firefox has permission: true
2019-09-13 13:09:00.751 608-692/? E/ConnectivityService: RemoteException caught trying to send a callback msg for NetworkRequest [ LISTEN id=81, [ Capabilities: INTERNET&NOT_RESTRICTED&TRUSTED&FOREGROUND] ]
2019-09-13 13:09:00.751 1174-1519/? D/Vizzini:MediaSessionLib.MediaSessionControllerStateMgr: Found valid active controller: org.mozilla.tv.firefox with state: 2
2019-09-13 13:09:00.752 248-248/? E/lowmemorykiller: Error writing /proc/26093/oom_score_adj; errno=22
2019-09-13 13:09:00.752 1174-1519/? D/Vizzini:MediaSessionLib.MediaSessionControllerStateMgr: org.mozilla.tv.firefox has permission: true
2019-09-13 13:09:00.753 1174-1519/? D/Vizzini:MediaSessionLib.MediaSessionControllerStateMgr: Found valid active controller: org.mozilla.tv.firefox with state: 2
2019-09-13 13:09:00.753 608-22002/? W/InputDispatcher: Attempted to unregister already unregistered input channel '23a63f6 PopupWindow:41bf168 (server)'
2019-09-13 13:09:00.753 1174-1519/? D/Vizzini:MediaSessionLib.MediaSessionControllerStateMgr: Session destroyed org.mozilla.tv.firefox
2019-09-13 13:09:00.754 1174-1519/? I/Vizzini_1.0.207874.0:ExternalPlaybackStateManager: Media State Update: ANDROID_MEDIA_SESSION is INACTIVE
2019-09-13 13:09:00.754 1174-1519/? I/Vizzini_1.0.207874.0:ExternalPlaybackStateManager: MediaStatus inactive or no media states to get context from.
2019-09-13 13:09:00.754 1174-1519/? I/Vizzini_1.0.207874.0:ExternalPlaybackStateManager: No active media, removing LocalMediaPlayerStateContext
2019-09-13 13:09:00.754 1174-1519/? I/Vizzini_1.0.207874.0:AlexaContextClient: Removing device context namespace: LocalMediaPlayer, name: PlaybackState
2019-09-13 13:09:00.754 243-1483/? D/qdqservice: QService::getSupportedResolutions: u4res_ntsc=0xb, u4res_pal=0x2c00, u4res_4k=0x0, u4res=0x2c0b
2019-09-13 13:09:00.755 243-1483/? I/qdqservice: QService::getAutoMode
2019-09-13 13:09:00.755 243-1483/? D/qdqservice: QService::getAutoMode: hdmiMode 13
2019-09-13 13:09:00.755 243-1483/? D/qdqservice: QService::convertOutputResCode: Found match: returning vic=16
2019-09-13 13:09:00.755 243-1483/? D/qdqservice: QService::getAutoMode: vicMode 16
2019-09-13 13:09:00.755 1174-1519/? I/BaseContextManager: Removing device context = [namespace=LocalMediaPlayer, name=PlaybackState]
2019-09-13 13:09:00.755 1174-1519/? V/Vizzini_1.0.207874.0:ExternalPlaybackStateManager: Current Media focus being cleared
2019-09-13 13:09:00.755 1174-1519/? D/AlexaFocusChannelSet: clearFocus for channel (content)
2019-09-13 13:09:00.755 1174-1519/? I/Vizzini_1.0.207874.0:ExternalPlaybackStateManager: We aren't associated with another device, don't send an event.
2019-09-13 13:09:00.755 1174-1519/? I/Vizzini_1.0.207874.0:AlexaContextClient: Removing device context namespace: LocalMediaPlayer, name: PlayerPreferences
2019-09-13 13:09:00.756 608-6231/? I/WindowManager: WIN DEATH: Window{2ef1e7e u0 org.mozilla.tv.firefox/org.mozilla.tv.firefox.MainActivity}
2019-09-13 13:09:00.756 608-6231/? W/InputDispatcher: Attempted to unregister already unregistered input channel '2ef1e7e org.mozilla.tv.firefox/org.mozilla.tv.firefox.MainActivity (server)'
2019-09-13 13:09:00.756 1174-1519/? I/BaseContextManager: Removing device context = [namespace=LocalMediaPlayer, name=PlayerPreferences]
2019-09-13 13:09:00.757 243-270/? D/qdqservice: QService::getSupportedResolutions: u4res_ntsc=0xb, u4res_pal=0x2c00, u4res_4k=0x0, u4res=0x2c0b
2019-09-13 13:09:00.758 243-270/? I/qdqservice: QService::getAutoMode
2019-09-13 13:09:00.758 243-270/? D/qdqservice: QService::getAutoMode: hdmiMode 13
2019-09-13 13:09:00.758 243-270/? D/qdqservice: QService::convertOutputResCode: Found match: returning vic=16
2019-09-13 13:09:00.758 243-270/? D/qdqservice: QService::getAutoMode: vicMode 16
2019-09-13 13:09:00.762 608-21433/? I/ActivityManager: Killing 26093:com.amazon.webview.chromium:sandboxed_process1/u0a170i23 (adj 0): isolated not needed
2019-09-13 13:09:00.765 243-270/? D/qdqservice: QService::getSupportedResolutions: u4res_ntsc=0xb, u4res_pal=0x2c00, u4res_4k=0x0, u4res=0x2c0b
2019-09-13 13:09:00.766 243-272/? I/qdqservice: QService::getAutoMode
2019-09-13 13:09:00.766 243-272/? D/qdqservice: QService::getAutoMode: hdmiMode 13
2019-09-13 13:09:00.766 243-272/? D/qdqservice: QService::convertOutputResCode: Found match: returning vic=16
2019-09-13 13:09:00.766 243-272/? D/qdqservice: QService::getAutoMode: vicMode 16
2019-09-13 13:09:00.768 243-272/? D/qdqservice: QService::getSupportedResolutions: u4res_ntsc=0xb, u4res_pal=0x2c00, u4res_4k=0x0, u4res=0x2c0b
2019-09-13 13:09:00.769 243-272/? I/qdqservice: QService::getAutoMode
2019-09-13 13:09:00.769 243-272/? D/qdqservice: QService::getAutoMode: hdmiMode 13
2019-09-13 13:09:00.769 243-272/? D/qdqservice: QService::convertOutputResCode: Found match: returning vic=16
2019-09-13 13:09:00.769 243-272/? D/qdqservice: QService::getAutoMode: vicMode 16
2019-09-13 13:09:00.769 608-719/? E/SELinux: avc:  denied  { log_internal_metric } for  scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:r:system_server:s0 tclass=amazon_policies permissive=0
2019-09-13 13:09:00.771 243-272/? D/qdqservice: QService::getSupportedResolutions: u4res_ntsc=0xb, u4res_pal=0x2c00, u4res_4k=0x0, u4res=0x2c0b
2019-09-13 13:09:00.772 243-272/? I/qdqservice: QService::getAutoMode
2019-09-13 13:09:00.772 243-272/? D/qdqservice: QService::getAutoMode: hdmiMode 13
2019-09-13 13:09:00.772 243-272/? D/qdqservice: QService::convertOutputResCode: Found match: returning vic=16
2019-09-13 13:09:00.772 243-272/? D/qdqservice: QService::getAutoMode: vicMode 16
2019-09-13 13:09:00.780 608-22002/? I/ActivityManager: Killing 25974:com.amazon.webview.chromium:AWVArcusServiceProcess/u0a118 (adj 903): empty #17
2019-09-13 13:09:00.782 1301-1301/? I/AppLifecycleListener: went foreground Activities: 1
2019-09-13 13:09:00.783 1301-1301/? I/NavMenuController: Request to addObserver received for observer: com.amazon.tv.launcher.ui.HomeActivity_vNext@514ce1c
2019-09-13 13:09:00.783 1301-1301/? I/NavMenuController: Informing cached scene to this observer
2019-09-13 13:09:00.783 1301-1301/? I/HomeActivity_vNext: Scene unchanged, ignoring ready event
2019-09-13 13:09:00.783 1301-1301/? I/KsoRefreshStateObservab: Refresh Previous State: INVISIBLE, Refresh Current State: VISIBLE
2019-09-13 13:09:00.785 608-628/? V/MouseModeService: packageName=com.amazon.tv.launcher activityName= mouseModeEnabled=false
2019-09-13 13:09:00.785 1301-1399/? I/AivConnectorManager: Attempting to initialize AivConnector
2019-09-13 13:09:00.786 1301-1399/? I/FTVCS:ComradeStateSyncManager: onBecameForeground
2019-09-13 13:09:00.786 286-396/? D/DolbyAudioHwDeviceProxy: setParameters(primary): continuous_audio_mode=0
2019-09-13 13:09:00.786 286-396/? D/DolbyAudioHwDeviceProxy: setParameters(a2dp): continuous_audio_mode=0
2019-09-13 13:09:00.786 1301-1399/? I/FTVCS:ComradeStateSyncManager: Requesting sync: HEARTBEAT
2019-09-13 13:09:00.787 286-396/? D/DolbyAudioHwDeviceProxy: getParameters(primary): hdmi_output_channel_mode;
2019-09-13 13:09:00.787 286-396/? I/DolbyAudioParameters: getParameters() return hdmi_output_channel_mode=0
2019-09-13 13:09:00.787 286-396/? D/DolbyAudioHwDeviceProxy: getParameters(a2dp): hdmi_output_channel_mode;
2019-09-13 13:09:00.787 286-396/? I/DolbyAudioParameters: getParameters() return hdmi_output_channel_mode=0
2019-09-13 13:09:00.787 1301-1399/? I/FTVCS:ComradeStateSyncManager: Not replacing job, existing job already found and no replace requested.
2019-09-13 13:09:00.787 1301-1399/? I/FTVCS:ComradeStateSyncManager: Sync request not scheduled: HEARTBEAT
2019-09-13 13:09:00.790 1174-1174/? D/Vizzini_1.0.207874.0:FocusServer: Activity switch detected, from package (null) to package (com.amazon.tv.launcher)
2019-09-13 13:09:00.790 1174-1174/? D/AlexaFocusChannelSet: Target (com.amazon.tv.launcher) has not reported an active namespace
2019-09-13 13:09:00.792 608-27172/? I/PointerController: PointerController setInvisible true
2019-09-13 13:09:00.796 1174-1174/? D/AlexaFocusVisualChannelSet: Acquiring visual focus for package (com.amazon.tv.launcher)
2019-09-13 13:09:00.797 1174-1174/? D/AlexaFocusChannelSet: acquireFocus namespace (LocalVoiceUI) channel (inFocus) client (com.amazon.tv.launcher) type (Package)
2019-09-13 13:09:00.797 1174-1174/? D/AlexaFocusFilter: Namespace (LocalVoiceUI) accepted as Local Application interface
2019-09-13 13:09:00.797 1174-1174/? D/AlexaFocusInFocusChannel: acquireFocus namespace (LocalVoiceUI) packageName (com.amazon.tv.launcher) client (null)
2019-09-13 13:09:00.797 1174-1174/? I/Vizzini_1.0.207874.0:FocusServer: Implicitly acquired focus for package (com.amazon.tv.launcher) namespace (LocalVoiceUI)
2019-09-13 13:09:00.797 1174-1174/? I/Vizzini_1.0.207874.0:ExternalPlaybackStateManager: We aren't associated with another device, don't send an event.
2019-09-13 13:09:00.797 1174-1174/? I/Vizzini_1.0.207874.0:ExternalPlaybackStateManager: Media State Update: CODEC_STATE_DETECTION is INACTIVE
2019-09-13 13:09:00.797 1174-1174/? I/Vizzini_1.0.207874.0:ExternalPlaybackStateManager: MediaStatus inactive or no media states to get context from.
2019-09-13 13:09:00.797 1174-1174/? I/Vizzini_1.0.207874.0:ExternalPlaybackStateManager: No active media, removing LocalMediaPlayerStateContext
2019-09-13 13:09:00.797 1174-1174/? I/Vizzini_1.0.207874.0:AlexaContextClient: Removing device context namespace: LocalMediaPlayer, name: PlaybackState
2019-09-13 13:09:00.799 1174-1174/? I/BaseContextManager: Removing device context = [namespace=LocalMediaPlayer, name=PlaybackState]
2019-09-13 13:09:00.799 1174-1174/? I/Vizzini_1.0.207874.0:ExternalPlaybackStateManager: We aren't associated with another device, don't send an event.
2019-09-13 13:09:00.802 1301-1301/? I/NavServerMenuLoader: Loading BrowseMenu from MB server
2019-09-13 13:09:00.803 1301-1301/? I/NavServerMenuLoader: BrowseMenu Loaded from MB.
2019-09-13 13:09:00.803 1301-1301/? I/NavServerMenuLoader: Home [[reftype=mb/screen,refid=HOME_DEFAULT]]
    Your Videos [[reftype=mb/screen,refid=YOUR_VIDEOS_DEFAULT]]
    Movies [[reftype=mb/screen,refid=MOVIES_DEFAULT]]
    TV Shows [[reftype=mb/screen,refid=TV_DEFAULT]]
2019-09-13 13:09:00.803 1301-1301/? I/NavMenuController: LoadServerMenuRunnable request created with priority: 27
2019-09-13 13:09:00.803 26171-26171/? I/AmazonVideo.profiler: Metric[name=PlaybackSdk-Service-bound, type=[Counter, ATVAndroidClientSDK-3.0.x.x, com.amazon.tv.launcher, ATVAndroidClientSDK-3.0.x.x-com.amazon.tv.launcher], val=1]
2019-09-13 13:09:00.807 1301-1301/? I/MobileWeblabClientManag: Feature treatment for feature FTV_ENGAGEMENT_ALEXA_HINTS_NON_STARK_211642 is : C_DEFAULT
2019-09-13 13:09:00.808 1301-1301/? I/MobileWeblabClientManag: Feature treatment for feature FTV_ENGAGEMENT_AR_FR_187881 is : C
2019-09-13 13:09:00.810 608-22002/? D/ActivityManager: cleanUpApplicationRecord -- 26093
2019-09-13 13:09:00.812 26171-26171/? I/AmazonVideo: SDK Bound Version: ATVAndroidClientSDK-3.0.x.x Source: com.amazon.tv.launcher
2019-09-13 13:09:00.817 1301-1301/? I/SleepIntentController: No matching row focus request found
2019-09-13 13:09:00.817 1301-1301/? I/MobileWeblabClientManag: Feature treatment for feature FTV_ENGAGEMENT_ALEXA_HINTS_NON_STARK_211642 is : C_DEFAULT
2019-09-13 13:09:00.819 608-624/? E/KernelUidCpuTimeReader: Failed to read uid_cputime: /proc/uid_cputime/show_uid_stat (No such file or directory)
2019-09-13 13:09:00.819 1301-1301/? I/MbTwoDNodePresenterDI: Row data not changed, not refreshing for row: Recent
2019-09-13 13:09:00.819 1301-1301/? I/MbTwoDNodePresenterDI: Row data not changed, not refreshing for row: Your Apps & Games
2019-09-13 13:09:00.819 1301-1301/? I/MbTwoDNodePresenterDI: Row data not changed, not refreshing for row: Featured Apps and Games
2019-09-13 13:09:00.819 1301-1301/? I/MbTwoDNodePresenterDI: Row data not changed, not refreshing for row: Recommends
2019-09-13 13:09:00.820 1301-1301/? I/MbTwoDNodePresenterDI: Row data not changed, not refreshing for row: On Now
2019-09-13 13:09:00.820 1301-1301/? I/MbTwoDNodePresenterDI: Row data not changed, not refreshing for row: Recommendation Testing Row
2019-09-13 13:09:00.820 1301-1301/? I/MbTwoDNodePresenterDI: Row data not changed, not refreshing for row: This Week on Fire TV
2019-09-13 13:09:00.820 1301-1301/? I/MbTwoDNodePresenterDI: Row data not changed, not refreshing for row: Top Free Games
2019-09-13 13:09:00.820 1301-1301/? I/MbTwoDNodePresenterDI: Row data not changed, not refreshing for row: Recommended Apps for You
2019-09-13 13:09:00.822 608-624/? E/KernelUidCpuTimeReader: failed to remove uid from uid_cputime module
    java.io.FileNotFoundException: /proc/uid_cputime/remove_uid_range (No such file or directory)
        at java.io.FileOutputStream.open(Native Method)
        at java.io.FileOutputStream.<init>(FileOutputStream.java:221)
        at java.io.FileOutputStream.<init>(FileOutputStream.java:108)
        at java.io.FileWriter.<init>(FileWriter.java:63)
        at com.android.internal.os.KernelUidCpuTimeReader.removeUid(KernelUidCpuTimeReader.java:158)
        at com.android.internal.os.BatteryStatsImpl.removeIsolatedUidLocked(BatteryStatsImpl.java:3163)
        at com.android.server.am.BatteryStatsService$BatteryStatsHandler.handleMessage(BatteryStatsService.java:141)
        at android.os.Handler.dispatchMessage(Handler.java:102)
        at android.os.Looper.loop(Looper.java:154)
        at android.os.HandlerThread.run(HandlerThread.java:61)
        at com.android.server.ServiceThread.run(ServiceThread.java:46)```
mcomella commented 5 years ago

athomasmoz, brampitoyo, and I ran into this while testing the product: we had a few failed passwords, ran into #2862, and then couldn't receive tabs. We tried signing out and signing back in but still couldn't receive tabs. We signed into a new device and could receive tabs there. On the original device, we installed an older build from not master and tried master again. We uninstalled the app on the original device and reinstalled it and we were able to receive tabs.

It's unclear what the issue was but it's possible we had a bad local build.

mcomella commented 5 years ago

I tried to sign in once and could not reproduce.

I installed a new build (I think, maybe have just cleared data) and tried to sign again: I was able to reproduce. I:

I wonder if the issue could be related to:

mcomella commented 5 years ago

After sending tabs, I'm unable to find any place Java gets called. I set breakpoints in the following locations:

None of these are ever called. I also set breakpoints in the following locations to try to debug the subscription:

Perhaps I should try this again when logging in to see if these get called.

mcomella commented 5 years ago

I signed into another device where push is working: the authentication/registration methods are only called when the user first signs in but not when cold starting the app. When receiving a message, AbstractAmazonPushService.onMessage is called first.

mcomella commented 5 years ago

I hit a second code path where messages are not received. I:

Unlike the last case from https://github.com/mozilla-mobile/firefox-tv/issues/2833#issuecomment-532763364 where onMessage is never called, onMessage is called and gets to AutoPushFeature.onMessageReceived. However, DeliveryManager.with(connection) silently fails to execute the block because connection.isInitialized returns false because api is null. This persists even after the app is force-stopped and restarted. Polling for tabs on startup works successfully but push does not.

Perhaps the ADM server on the device gets confused if you don't explicitly unregister your app before registering your app again.

mcomella commented 5 years ago

I hit a second code path where messages are not received. I:

Given the separate code path and STR, I broke this into a separate issue: https://github.com/mozilla-mobile/firefox-tv/issues/2867 This bug will remain about not being able to send tabs when Java is not called at all.

mcomella commented 5 years ago

I'm struggling to reproduce this. I've tried:

It's possible this happens randomly (e.g. a race condition) or that I confused #2867 with this bug. To reiterate, my distinction between that clear data bug and this one is that in this bug it did not seem that Java was getting called at all by ADM (because my debugger didn't get stopped in AbstractAmazonPushService.onMessage).

abodea commented 5 years ago

Hi please note that I'm able to reproduce this issue only when sending a tab from Nightly Desktop browser. When I'm sending from RC Desktop there is no problem. @mcomella can you please try to use Nightly Desktop?

mcomella commented 5 years ago

Hi please note that I'm able to reproduce this issue only when sending a tab from Nightly Desktop browser. When I'm sending from RC Desktop there is no problem.

This also doesn't work in Fenix so this is likely a problem with the library or the FxA server-side. We filed https://github.com/mozilla/fxa/issues/2546.

I haven't tested with Firefox Nightly but I was still able to reproduce this issue once (that is separate from #2867) so I won't repurpose this bug to track that upstream fxa issue.

mcomella commented 5 years ago

I haven't tested with Firefox Nightly but I was still able to reproduce this issue once (that is separate from #2867) so I won't repurpose this bug to track that upstream fxa issue.

Actually, I filed https://github.com/mozilla-mobile/firefox-tv/issues/2877 to track the upstream cannot-send-from-Nightly issue. This bug will remain about trying to reproduce that issue where Java is not called at all when a tab is sent (which may not actually be a bug).

mcomella commented 5 years ago

No STR so I can't actively work on this: unassigning.

mcomella commented 5 years ago

@abodea Since we fixed #2867, have you seen this again on non-Nightly desktop builds (the issue for Nightly builds is #2877)?

If you haven't seen it again, it's possible this was a local build issue or that I mis-diagnosed the issue (e.g. confused it with #2867).

@athomasmoz If Andrei hasn't seen this issue and we want to make sure it's not really an issue, we could compare the telemetry on our side (tab received) with the telemetry on the desktop side (tab sent to FFTV device) to see if users are not receiving a non-trivial number of tabs. This would require work from:

Is this something you'd be interested in?