Closed Bug 982554 Opened 10 years ago Closed 10 years ago

[Tarako] [EMAIL] Notification for E-mail cannot be display

Categories

(Firefox OS Graveyard :: Gaia::E-Mail, defect)

Other
Other
defect
Not set
normal

Tracking

(blocking-b2g:1.3T+, b2g-v1.3T affected)

VERIFIED WORKSFORME
1.4 S5 (11apr)
blocking-b2g 1.3T+
Tracking Status
b2g-v1.3T --- affected

People

(Reporter: angelc04, Assigned: asuth)

References

Details

(Keywords: smoketest)

Attachments

(8 files)

moztrap Case #10744: https://moztrap.mozilla.org/manage/case/10744/

Reproduce steps:
1. Open E-mail app
   If no account has been set up on the device the first time E-mail set up will be displayed.
2. Set up an e-mail account
   Drop down and toggle will be displayed after inputting credentials to be able to turn on notification.(Make sure it is toggled on and make sure the "Check for new messages" is set to a time and not manual)
3. Tap the Home button
4. Send e-mail to test device and wait for a while
  [actual] No notification appears.

  [excepted] A notification will be display on the top of the phone when the phone auto checks for new messages.


Tarako 1.3t build:20140312064823
gaia: a1e70877
Please provide the information requested at https://wiki.mozilla.org/Gaia/Email/RequiredBugInfo.
This bug is not actionable without information.
Flags: needinfo?(pcheng)
Test environment
--------------------------------------------------------------------------
Device: Tarako

Build: v1.3t 20140312064823
gaia: "a1e70877a251448160a6e52e52ec418f8516c8ee"
gecko: "7780260787cd36929bba12fcc12022b6e8150eca"

Email Account: Tested using both gmail and hotmail. Neither of them received email notification.

WIFI: enabled


Reproduce steps
----------------------------------------------------------------------------
1. Open E-mail app
2. Set up an e-mail account using gmail or hotmail
   (Set "Check for new messages" to a time and not manual)
3. Tap the Home button
4. Send e-mail to test device and wait for a while
  [actual] No notification appears.

  [excepted] A notification will be display on the top of the phone when the phone auto checks for new messages.


I think this might be because of Tarako's limit memory and it kills Email app when we send it to background. So no notification could be received.
Flags: needinfo?(pcheng)
blocking-b2g: --- → 1.3T?
pcheng, if it is killed due to OOM, we should follow :
https://wiki.mozilla.org/B2G/Debugging_OOMs#Step_1:_Verify_that_it.27s_actually_an_OOM

Also to note you can get about_memory information as well through : 
https://wiki.mozilla.org/B2G/QA/Tips_And_Tricks#Debugging_OOMs

Can you collect this information and place it in this bug please?
Flags: needinfo?(pcheng)
blocking-b2g: 1.3T? → 1.3T+
One of the core things we're looking for from https://wiki.mozilla.org/Gaia/Email/RequiredBugInfo is the logcat that shows us what the e-mail app was actually doing.  Also relevant is knowing:
- Does the device have a cellular data connection
- whether the device is charging when you are running the tests

Note that we almost certainly expect gmail sync to not work because of bug 977867 which is only fixed on v1.4/master right now.  hotmail is a better test right now, but for IMAP testing, anything but gmail should also work.  (Yahoo, mozilla.com zimbra, etc.)
Flags: needinfo?(nhirata.bugzilla)
Keywords: smoketest
Attached file adb.log
Test start at : 03-13 13:59:13.650
Flags: needinfo?(pcheng)
@Naoki, this is not OOM crash(I didn't find sigkill from adb shell dmesg output). Tarako will kill Email app if it's in background.

@asuth, please see attached adb logcat and answers for ur questions bellow.
- Does the device have a cellular data connection ---- NO. I was using WIFI for testing.
- whether the device is charging when you are running the tests. ---- NO.
This should be the same issue with bug 977867 since Email app was killed. Since this blocks smoketest, is it possible to include the fix in 1.3t?
Andrew, will you be able to take this bug? Thanks
Flags: needinfo?(bugmail)
tl;dr: I am declaring this a platform/device network problem, internet connection problem with the wi-fi network in use, or known bug 907028.  XHR requests to the hotmail servers are repeatedly timing out after 30 seconds.  The e-mail app needs a working network to perform periodic sync and the network is clearly flakey.

There is a potential e-mail mitigation of adding more retries to the core sync process, but that might not be great either, instead of taking 30 seconds to fail, we could end up taking 60 or 90 seconds to fail.


(In reply to pcheng from comment #6)
> @asuth, please see attached adb logcat and answers for ur questions bellow.
> - Does the device have a cellular data connection ---- NO. I was using WIFI
> for testing.
> - whether the device is charging when you are running the tests. ---- NO.
> This should be the same issue with bug 977867 since Email app was killed.
> Since this blocks smoketest, is it possible to include the fix in 1.3t?

We don't expect sync to work at all in this case.  If you are using wi-fi and the device is not charging (connected via powered USB), then the only network connection (wi-fi) will be turned off when the screen is off by default behaviour.  The e-mail app does not / is not able to turn on the wi-fi when it is off.  This is bug 907028.

Although I am confused because it does look like the Tarako device is staying connected to wi-fi when the screen turns off?  E-mail does seem to always think it is online.  Is it possible there is a platform bug that lies about the status of the wi-fi connection?  That would definitely explain the timeouts.


I only see indication of ActiveSync activity, consistent with my comment about gmail IMAP being broken on v1.3/v1.3T right now.  The primary problem seems to be ActiveSync XHR timeouts.  Specifically, I see 3 syncs:

=== sync 1: fails because of XHR timeout in withConnection() code-path that is fatal
03-13 13:51:38.010 I/GeckoDump( 2745): LOG: email oncronsyncstart: 0
03-13 13:52:08.440 I/Gecko   ( 2745): WERR: Error: Error getting OPTIONS URL
03-13 13:52:08.450 I/Gecko   ( 2745): WERR: Error connecting to ActiveSync: Error: Error getting OPTIONS URL
03-13 13:52:08.450 I/Gecko   ( 2745): WLOG: Sync Completed! undefined messages synced
03-13 13:52:08.490 I/GeckoDump( 2745): LOG: email oncronsyncstop: 0


=== sync 2: complicated overlap of UI-triggered behaviour and periodic sync:
-- the UI is displayed:
03-13 13:56:31.550 I/GeckoDump( 3038): LOG: pushCard for type: message_list

-- I don't think a sync is triggered because we're within the 10 minute window where we don't auto-refresh.
-- a downloadBodies is enqueued; presumably for snippet retrieval
03-13 13:56:34.500 I/Gecko   ( 3038): WLOG: queueOp 0 downloadBodies
03-13 13:56:34.500 I/Gecko   ( 3038): WLOG: runOp(do: {"type":"downloadBodies","longtermId":"0/1","lifecycle":"do","localStatus":"done","serverStatu
s":"doing","tryCount":0,"humanOp":"downloadBodies","messages":[{"s)

-- the sync timer fires, probably scheduling a sync, but in the mutex queue after the snippet fetch
03-13 13:56:38.130 I/GeckoDump( 3038): LOG: email oncronsyncstart: 0

-- the UI gives up on the snippet request (6 second delay) and issues another one
03-13 13:56:45.250 I/Gecko   ( 3038): WLOG: queueOp 0 downloadBodies

-- the snippet-fetch command times-out.  the inference is that the OPTIONS request did succeed
03-13 13:57:13.880 I/Gecko   ( 3038): WERR: Error: Error getting command URL
03-13 13:57:13.900 I/Gecko   ( 3038): WERR: Error: Error getting command URL

-- the snippet-fetch job actually completes (having failed). delay is weird. this will release the mutex for the sync logic.
03-13 13:57:23.780 I/Gecko   ( 3038): WLOG: runOp_end(do: {"type":"downloadBodies","longtermId":"0/1","lifecycle":"do","localStatus":"done","serverStatus":"doing","tryCount":0,"humanOp":"downloadBodies","messages":[{"s)

-- the snippet-fetch job gets rescheduled, but it won't be able to acquire the mutex
03-13 13:57:23.840 I/Gecko   ( 3038): WLOG: runOp(do: {"type":"downloadBodies","longtermId":"0/1","lifecycle":"do","localStatus":"done","serverStatus":"doing","tryCount":5,"humanOp":"downloadBodies","messages":[{"s)

-- the sync process completes acceptably, but now it wants a snippet and the UI may also have issued another snippet fetch request
03-13 13:57:31.810 I/Gecko   ( 3038): WLOG: Sync completed: added 1, changed 0, deleted 0
03-13 13:57:31.820 I/Gecko   ( 3038): WLOG: onNewHeader: [object Object]
03-13 13:57:31.820 I/Gecko   ( 3038): WLOG: Sync Completed! 1 messages synced
03-13 13:57:31.860 I/Gecko   ( 3038): WLOG: cronsync: Asking for snippets for 1 headers
03-13 13:57:31.860 I/Gecko   ( 3038): WLOG: queueOp 0 downloadBodies
03-13 13:57:32.160 I/Gecko   ( 3038): WLOG: queueOp 0 downloadBodies

-- it seems like the UI must have issued a sync request too at some point?
03-13 13:57:33.360 I/Gecko   ( 3038): WLOG: Sync completed with empty response
03-13 13:57:33.360 I/Gecko   ( 3038): WLOG: Sync Completed! 0 messages synced

-- the snippet fetch runs to completion, as do a whole bunch more that had accumulated
03-13 13:57:34.320 I/Gecko   ( 3038): WLOG: runOp_end(do: {"type":"downloadBodies","longtermId":"0/1","lifecycle":"do","localStatus":"done","serverStatus":"doing","tryCount":5,"humanOp":"downloadBodies","messages":[{"s)
03-13 13:57:34.320 I/Gecko   ( 3038): 
03-13 13:57:34.340 I/Gecko   ( 3038): WLOG: runOp(do: {"type":"downloadBodies","longtermId":"0/2","lifecycle":"do","localStatus":"done","serverStatus":"doing","tryCount":0,"humanOp":"downloadBodies","messages":[{"s)
03-13 13:57:34.370 I/Gecko   ( 3038): WLOG: runOp_end(do: {"type":"downloadBodies","longtermId":"0/2","lifecycle":"do","localStatus":"done","serverStatus":"doing","tryCount":0,"humanOp":"downloadBodies","messages":[{"s)
03-13 13:57:34.370 I/Gecko   ( 3038): 
03-13 13:57:34.370 I/Gecko   ( 3038): WLOG: runOp(do: {"type":"downloadBodies","longtermId":"0/3","lifecycle":"do","localStatus":"done","serverStatus":"doing","tryCount":0,"humanOp":"downloadBodies","messages":[{"i)
03-13 13:57:34.950 I/GeckoDump( 3038): LOG: htmlCache.save: 16013 in 8 segments
03-13 13:57:35.210 I/Gecko   ( 3038): WLOG: runOp_end(do: {"type":"downloadBodies","longtermId":"0/3","lifecycle":"do","localStatus":"done","serverStatus":"doing","tryCount":0,"humanOp":"downloadBodies","messages":[{"i)

-- cronsync notifies:
03-13 13:57:35.220 I/Gecko   ( 3038): WLOG: cronsync: Notifying for 1 headers

-- another snippet fetch runs:
03-13 13:57:35.240 I/Gecko   ( 3038): WLOG: runOp(do: {"type":"downloadBodies","longtermId":"0/4","lifecycle":"do","localStatus":"done","serverStatus":"doing","tryCount":0,"humanOp":"downloadBodies","messages":[{"s)
03-13 13:57:35.280 I/Gecko   ( 3038): WLOG: runOp_end(do: {"type":"downloadBodies","longtermId":"0/4","lifecycle":"do","localStatus":"done","serverStatus":"doing","tryCount":0,"humanOp":"downloadBodies","messages":[{"s)

-- cronsync completes, but leaves the app open because the UI was shown
03-13 13:57:35.430 I/GeckoDump( 3038): LOG: email oncronsyncstop: 0

=== sync 3: cronsync sync works but the snippet fetch appears to be destined for a timeout; the logcat ends right before our timeout would fire.

03-13 14:01:38.190 I/GeckoDump( 3038): LOG: email oncronsyncstart: 0
03-13 14:01:38.200 I/GeckoDump( 3038): LOG: cronsync-main: ensureSync called
03-13 14:01:38.240 I/GeckoDump( 3038): LOG: cronsync-main: success: mozAlarms.add for IDs: 0 at 300000ms
03-13 14:01:38.250 I/Gecko   ( 3038): WLOG: cronsync: received an syncEnsured via a message handler
03-13 14:01:38.250 I/Gecko   ( 3038): 
03-13 14:01:47.760 I/Gecko   ( 3038): WLOG: Sync completed: added 1, changed 0, deleted 0
03-13 14:01:47.760 I/Gecko   ( 3038): WLOG: onNewHeader: [object Object]
03-13 14:01:47.770 I/Gecko   ( 3038): WLOG: Sync Completed! 1 messages synced
03-13 14:01:47.770 I/Gecko   ( 3038): WLOG: cronsync: Asking for snippets for 1 headers
03-13 14:01:47.770 I/Gecko   ( 3038): 
03-13 14:01:47.780 I/Gecko   ( 3038): WLOG: queueOp 0 downloadBodies
03-13 14:01:47.780 I/Gecko   ( 3038): WLOG: runOp(do: {"type":"downloadBodies","longtermId":"0/5","lifecycle":"do","localStatus":"done","serverStatu
s":"doing","tryCount":0,"humanOp":"downloadBodies","messages":[{"i)
03-13 14:01:47.910 I/Gecko   ( 3038): WLOG: queueOp 0 downloadBodies


====

Aside: the log indicated that at one point gmail thinks your are connecting from a suspicious IP or something like that, which it appears you corrected.  Better processing that error is bug 847803.
Flags: needinfo?(bugmail)
(In reply to Andrew Sutherland (:asuth) from comment #8)
> tl;dr: I am declaring this a platform/device network problem, internet
> connection problem with the wi-fi network in use, or known bug 907028.  XHR
> requests to the hotmail servers are repeatedly timing out after 30 seconds. 
> The e-mail app needs a working network to perform periodic sync and the
> network is clearly flakey.

Can QA test with different Tarako devices? to make sure this is not a single device connectivity issue? iirc, Wifi isn't completely stable on tarako yet
Flags: needinfo?(pcheng)
Keywords: qawanted
The app was killed before any notification was given.  This is with : user_pref("browser.dom.window.dump.enabled", true);

772 was the email process; I used a hotmail email address.  This happened on 2 different tarakos.

03-13 13:19:53.030: I/Gecko:ProcessPriorityManager(81): [Homescreen, child-id=2, pid=387] Changing priority from BACKGROUND_HOMESCREEN:CPU_LOW to FOREGROUND:CPU_LOW.
03-13 13:19:53.030: I/Gonk(81): Setting nice for pid 387 to 18
03-13 13:19:53.030: I/Gonk(81): Changed nice for pid 387 from 18 to 18.
03-13 13:19:53.030: I/Gecko:ProcessPriorityManager(81): KillBackgroundApps
03-13 13:19:53.030: I/Gecko:ProcessPriorityManager(81): About to force kill pid: 772
03-13 13:19:53.030: I/Gecko:ProcessPriorityManager(81): Remove ChildID(7) from LRU pool
03-13 13:19:53.140: W/WifiHW(81): wifi_command: SIGNAL_POLL
03-13 13:19:53.140: D/wpa_supplicant(405): nl80211: survey data missing!
03-13 13:19:53.150: E/[Gralloc-ERROR](81): int gralloc_unregister_buffer(const gralloc_module_t*, const native_handle_t*):274 Trying to unregister buffer 0x4411bec0 from process 81 that was not created in current process: 81
03-13 13:19:53.150: E/[Gralloc-ERROR](81): int gralloc_unregister_buffer(const gralloc_module_t*, const native_handle_t*):274 Trying to unregister buffer 0x44175fb0 from process 81 that was not created in current process: 81
03-13 13:19:53.200: I/Gecko(81): [Parent 81] WARNING: pipe error (95): Connection reset by peer: file /var/lib/jenkins/jobs/B2G.v1.3.0.Tarako/workspace/gecko/ipc/chromium/src/chrome/common/ipc_channel_posix.cc, line 446
03-13 13:19:53.200: I/Gecko(81): ###!!! [Parent][MessageChannel] Error: Channel error: cannot send/recv
03-13 13:19:53.230: I/Gecko:ProcessPriorityManager(81): [child-id=7, pid=-1] Destroying ParticularProcessPriorityManager.
03-13 13:19:53.230: I/Gecko(81): [Parent 81] WARNING: waitpid failed pid:772 errno:10: file /var/lib/jenkins/jobs/B2G.v1.3.0.Tarako/workspace/gecko/ipc/chromium/src/base/process_util_posix.cc, line 254
03-13 13:19:53.460: E/[Gralloc-ERROR](81): int gralloc_register_buffer(const gralloc_module_t*, const native_handle_t*):79 Unable to register handle 0x44c99560 coming from different process: 81
03-13 13:19:53.460: E/[Gralloc-ERROR](81): int gralloc_register_buffer(const gralloc_module_t*, const native_handle_t*):79 Unable to register handle 0x44c99600 coming from different process: 81
03-13 13:19:53.480: E/[Gralloc-ERROR](81): int gralloc_register_buffer(const gralloc_module_t*, const native_handle_t*):79 Unable to register handle 0x44c996a0 coming from different process: 81
03-13 13:19:53.480: E/[Gralloc-ERROR](81): int gralloc_register_buffer(const gralloc_module_t*, const native_handle_t*):79 Unable to register handle 0x44c99740 coming from different process: 81
03-13 13:19:53.490: E/[Gralloc-ERROR](81): int gralloc_register_buffer(const gralloc_module_t*, const native_handle_t*):79 Unable to register handle 0x44c997e0 coming from different process: 81
03-13 13:19:53.490: E/[Gralloc-ERROR](81): int gralloc_register_buffer(const gralloc_module_t*, const native_handle_t*):79 Unable to register handle 0x44c99880 coming from different process: 81
03-13 13:19:53.880: I/GeckoDump(81): XXX FIXME : Got a mozContentEvent: nfc-hardware-state-change
03-13 13:19:53.900: I/GeckoDump(81): XXX FIXME : Got a mozContentEvent: nfc-hardware-state-change
03-13 13:19:53.980: E/[Gralloc-ERROR](81): int gralloc_unregister_buffer(const gralloc_module_t*, const native_handle_t*):274 Trying to unregister buffer 0x44c99600 from process 81 that was not created in current process: 81
03-13 13:19:53.980: E/[Gralloc-ERROR](81): int gralloc_unregister_buffer(const gralloc_module_t*, const native_handle_t*):274 Trying to unregister buffer 0x44c99560 from process 81 that was not created in current process: 81
03-13 13:19:53.990: E/[Gralloc-ERROR](81): int gralloc_unregister_buffer(const gralloc_module_t*, const native_handle_t*):274 Trying to unregister buffer 0x44c99740 from process 81 that was not created in current process: 81
03-13 13:19:53.990: E/[Gralloc-ERROR](81): int gralloc_unregister_buffer(const gralloc_module_t*, const native_handle_t*):274 Trying to unregister buffer 0x44c996a0 from process 81 that was not created in current process: 81
03-13 13:19:53.990: E/[Gralloc-ERROR](81): int gralloc_unregister_buffer(const gralloc_module_t*, const native_handle_t*):274 Trying to unregister buffer 0x44c99880 from process 81 that was not created in current process: 81
03-13 13:19:53.990: E/[Gralloc-ERROR](81): int gralloc_unregister_buffer(const gralloc_module_t*, const native_handle_t*):274 Trying to unregister buffer 0x44c997e0 from process 81 that was not created in current process: 81
03-13 13:19:55.230: I/Gecko(81): [Parent 81] WARNING: waitpid failed pid:772 errno:10: file /var/lib/jenkins/jobs/B2G.v1.3.0.Tarako/workspace/gecko/ipc/chromium/src/base/process_util_posix.cc, line 254
03-13 13:19:55.230: I/Gecko(81): [Parent 81] WARNING: Failed to deliver SIGKILL to 772!(3).: file /var/lib/jenkins/jobs/B2G.v1.3.0.Tarako/workspace/gecko/ipc/chromium/src/chrome/common/process_watcher_posix_sigchld.cc, line 118
03-13 13:19:58.140: W/WifiHW(81): wifi_command: SIGNAL_POLL
Flags: needinfo?(nhirata.bugzilla)
Attached file logcat.txt
Fuller logcat from the time that email app was relaunched, set to background and an email to the hotmail account was sent.  Account was setup with ActiveSync

E-Mail           app_812   812   356   75648  28644 ffffffff 400b5518 S /system/b2g/plugin-container


It looks like email app gets killed when the phone goes to sleep?  I'm going to try another run of keeping the phone awake and waiting.
This time I logcatted with the email app in the background and I kept the device awake.  This is a hotmail account w/ sync every 5 minutes.

No notification appeared after the data sync.  Email app was still alive in the background ( E-Mail 1257 )

It looks like you do have to keep the phone awake else the email app will get killed from sleep/wake.
Attached file 3rd attempt logcat.txt
rebooted the phone and tried the same thing again: hotmail with the phone kept away and email in the background. email pid : 602

I got an error in the notification : 
03-13 14:01:22.970: I/Gecko(81): A coding exception was thrown in a Promise resolution callback.
03-13 14:01:22.970: I/Gecko(81): Full message: TypeError: this.byTag[origin] is undefined
Sounds like Naoki confirmed this is reproducible on different tarako devices & on a different network, so I'm removing qawanted here.
Keywords: qawanted
Flags: needinfo?(pcheng)
Andrew, can you please take a further look? Thanks
Flags: needinfo?(bugmail)
Keywords: smoketest
(In reply to Naoki Hirata :nhirata (please use needinfo instead of cc) from comment #13)
> 03-13 14:01:22.970: I/Gecko(81): A coding exception was thrown in a Promise
> resolution callback.
> 03-13 14:01:22.970: I/Gecko(81): Full message: TypeError: this.byTag[origin]
> is undefined

This appears to be bug 963130 which was uplifted to 1.3t on Friday, March 14th.  Context:
https://hg.mozilla.org/releases/mozilla-b2g28_v1_3t/rev/57f27d290aea
https://hg.mozilla.org/releases/mozilla-b2g28_v1_3t/pushloghtml?changeset=57f27d290aea

Note that bug 962977 also was uplifted and it relates to bugs in the lower notification levels.

I looked at the remainder of the logs provided, e-mail appears to work fine and run to completion during its syncs.  So I expect this should be WFM once we confirm that things work fine with a working notifications layer.
Flags: needinfo?(bugmail)
Keywords: qawanted
We're still seeing an error:
I/Gecko   ( 3499): WERR: Error: Error getting command URL
I/Gecko   ( 3499): WERR: Error syncing folder: Error: Error getting command URL
I/Gecko   ( 3499): WLOG: Sync Completed! undefined messages synced
I/GeckoDump( 3499): LOG: email oncronsyncstop: 0
I/GeckoDump( 3499): LOG: email: clearing wake locks for "id0"

Using: 
Gaia      15385efaf840090391d182d821eaeda6d25cf0e0
caution: filename not matched:  chrome/toolkit/content/global/buildconfig.html
BuildID   20140317060055
Version   28.0
ro.build.version.incremental=113
ro.build.date=Mon Mar 17 06:10:08 CST 2014
Tarako
That looks like a network problem that the e-mail app is handling appropriately.  It's just an XMLHttpRequest.  It's on the RIL or system or the network being used.  If you have a tcpdump that covers the request we can have a better idea of the exact cause, but there's not much the e-mail app can do about it.
Also, please make sure your logcats are generated using "-v time" so it's more obvious when the problem is a timeout versus an explicit failure path.
Target Milestone: --- → 1.4 S4 (28mar)
Attached file logcat.txt
Corresponding logcat from launch of email app to placing it in the background and waiting for the message to try to come out.
Thank you for the pcap!  Unfortunately, the logcat and pcap indicate that periodic sync was successful in this case and that 1 message was notified for.  Did you see a notification?  If not, are you sure the build has the 1.3T notification fixes?
Flags: needinfo?(nhirata.bugzilla)
I also tested in today's build 20140318104052, but still get no notification.
gaia revision="abf210d0ea2f6bf1c43be46fde67521aa36af0db"
gecko revision="3fb98dffed72c590ad831ae56a711ce406239720"

I checked adb locat. It seems email periodic sync works. But not sure why I get no notification.
I'll see if there are any uplifts we are missing and test periodic sync on a buri/hamachi with a 1.3T build since I don't have a tarako and the notifications bug does not seem likely to be device-specific.
Assignee: nobody → bugmail
Status: NEW → ASSIGNED
It seems like Andrew trying to fix this without an actual target device is like shooting fish in a barrel.  What needs to happen to get him a device?
I believe Dylan has a device that we can ship to asuth
Flags: needinfo?(doliver)
Shipped it today.
Flags: needinfo?(doliver)
Whiteboard: [priority]
I didn't see this bug on today's build:
gaia: "8132b88334f61288060a2680857c54c7af82cdc5"
gecko: "57625761da9e5c35d1ddd516221ce274a3575d15"
build id: 20140324121117
I guess that makes this a works for me then per comment 29.
Status: ASSIGNED → RESOLVED
Closed: 10 years ago
Resolution: --- → WORKSFORME
Attached file adblog_0326.log
adb log for build 20140326061134. test starts at: 03-26 19:40:24.847
Attached file adb log_0324.log
adb log for build 20140324121117
tests start at 03-26 19:23:29.740
I need to reopen this bug since it happens on following build again:

- Gaia f6a7afd0d716f7a38dfc1808ee0aab3e06ba2f1d
- Gecko fb7149d9b320d939d716011f865ec34661ebc353
- BuildID 20140326061134
- Version 28.1
- ro.build.version.incremental=68
- ro.build.date=Wed Mar 26 06:17:50 CST 2014


* ADB logcat for build 20140326061134. It seems it got a MessageChannel error.  for details, please see attachment adblog_0326.log 
----------------------------------------------------------------------------
03-26 18:47:51.032 W/WifiHW  (   81): wifi_command: SIGNAL_POLL
03-26 18:47:51.032 D/wpa_supplicant(  396): nl80211: survey data missing!
03-26 18:47:52.822 I/Gonk    (   81): Setting nice for pid 1028 to 18
03-26 18:47:52.822 I/Gonk    (   81): Changed nice for pid 1028 from 0 to 18.
03-26 18:47:53.162 I/GeckoDump(  864): [32mLOG: cronsync-main: wake locks acquired: [object MozWakeLock] for account IDs: 0[0m
03-26 18:47:53.592 I/Gecko   (  864): [32mWLOG: Email knows that it is: online and previously was: online[0m
03-26 18:47:53.602 I/Gecko   (  864): [32mWLOG: deferring getConfig call until ready[0m
03-26 18:47:53.602 I/Gecko   (  864): [32mWLOG: cronsync: received an alarm via a message handler
03-26 18:47:53.602 I/Gecko   (  864): [0m
03-26 18:47:53.622 I/Gecko   (  864): [32mWLOG: main thread reports DB ready[0m
03-26 18:47:53.622 I/Gecko   (  864): [32mWLOG: issuing getConfig call to main thread[0m
03-26 18:47:53.902 I/Gonk    (   81): Setting nice for pid 864 to 18
03-26 18:47:53.902 I/Gonk    (   81): Changed nice for pid 864 from 7 to 18.
03-26 18:47:54.002 I/Gecko   (   81): 
03-26 18:47:54.002 I/Gecko   (   81): ###!!! [Parent][MessageChannel] Error: Channel error: cannot send/recv
03-26 18:47:54.002 I/Gecko   (   81): 
03-26 18:47:54.012 I/Gecko   (   81): [Parent 81] WARNING: waitpid failed pid:864 errno:10: file /var/lib/jenkins/jobs/B2G.v1.3.0.Tarako.v1.3t/workspace/gecko/ipc/chromium/src/base/process_util_posix.cc, line 254
03-26 18:47:54.702 I/Gecko   ( 1028): ###################################### forms.js loaded
03-26 18:47:54.732 I/Gecko   ( 1028): ############################### browserElementPanning.js loaded
03-26 18:47:54.752 I/Gecko   ( 1028): ######################## BrowserElementChildPreload.js loaded
03-26 18:47:56.012 I/Gecko   (   81): [Parent 81] WARNING: waitpid failed pid:864 errno:10: file /var/lib/jenkins/jobs/B2G.v1.3.0.Tarako.v1.3t/workspace/gecko/ipc/chromium/src/base/process_util_posix.cc, line 254
03-26 18:47:56.012 I/Gecko   (   81): [Parent 81] WARNING: Failed to deliver SIGKILL to 864!(3).: file /var/lib/jenkins/jobs/B2G.v1.3.0.Tarako.v1.3t/workspace/gecko/ipc/chromium/src/chrome/common/process_watcher_posix_sigchld.cc, line 118
03-26 18:47:56.032 W/WifiHW  (   81): wifi_command: SIGNAL_POLL


* Logcat for build 20140324121117 on which this feature works is also attached as: attachment 
adb log_0324.log. From the log you can see notifications are received successfully.
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
BTW, I also tested on build 20140325060053 and can also reproduce this (using the same device/network/steps). But actually, this build has the same gaia/gecko/gonk revision with build 20140324121117.

It's weird that I can reproduce on 20140325060053 but not 20140324121117.
Andrew, do you mind taking another look at this? thanks
We happenned to get the notification once on today's build. And then later we can consistently reproduced this bug again. 

It seems to be a random bug with very high reproduce rate(9/10). It may caused by some memory leak or memory pressure which we could not get a clue now.
So I think it would be better to keep this on track for future builds.

The build today: 
Gaia d8ff994bd96c37ba9a93c343932a5441a78a0eec
Gecko 6db37b3f76b4fe2aa6f8fb5ae9e036ed99344772
BuildID 20140327060053
Yes, I'm still working this by cleaning up our JS marionette tests so I can just run a tarako (or other device) in constant automation mode while also automatically monitoring key stuff like processes, etc. and then automatically pull the state out of the guts of the relevant system app stuff / gecko backend stuff.
Flags: needinfo?(bugmail)
Turns out I was right originally - this does fall under our 49 smoketest list, so re-adding the smoketest keyword.
Keywords: smoketest
I tried about 8 times  on build 20140328060053, the notification for email can be displayed.
Let's keep this bug open, and test for several builds.

-----------------------------------------------
Gaia ecbd79aab76e119a7987092b59cbafc97f7ba72f
Gecko f23735074dc673457426afa5d87a67f934a18a9b
BuildID 20140328060053
Version 28.1
Whiteboard: [priority]
Can we get on the same page on the STR that is used to reproduce this? We're jumping all over the place here saying this & isn't reproducing on certain days, which is confusing people on the bug.
Gaia      ecbd79aab76e119a7987092b59cbafc97f7ba72f
Gecko     f23735074dc673457426afa5d87a67f934a18a9b
BuildID   20140328060053
Version   28.1
ro.build.version.incremental=70
ro.build.date=Fri Mar 28 06:17:40 CST 2014

I'm testing this on today's build and it seems to be working fine;  I just had two different notations come in on two different phones according to the original STR.  I'll remove the smoketest blocking flag, but with one caveat - my display timeout settings are never.  What are your display timeout settings?
So I AM seeing a different behavior depending on whether I'm using a data connection or wifi.  When connecting over Wifi, I am not getting the notification. I'll try to repro again and attach a logcat.
Note that under wifi, if that is the only data connection available, the phone turns off wifi after a time when the screen goes off, if not connected to power, so email cannot successfully connect in that situation. This is a known issue, tracked in bug 907028.

So, to summarize, in the cases where wifi is the only data connection available, and the phone turns off wifi, the periodic sync in email will not work.
Aaaand, I completely take that back.  I AM seeing this issue repro about 5/7 times regardless of the connection type.   So this bug is still valid, IMO.
So to sum up, the mails are coming in, regardless of the connection type.  The problem is that we're not seeing the notifications.
Target Milestone: 1.4 S4 (28mar) → 1.4 S5 (11apr)
As a new-sprint update on the e-mail engineering side, the plan continues to be that of comment 37.  Get the integration tests working, run them semi-manually against the Tarako, hopefully the problem becomes super obvious.  I'm explicitly marking the dependency to this end.  If I don't have significant progress by the end of the week (juggling some other blockers too) we'll revisit and look at asking for help from systems front-end.  (The theory is that right now we can have a net saving of effort by letting our integration tests do the heavy lifting.)
Depends on: 975588
Running smoketest on todays Tarako build (2014/04/04) and this issue is no longer occurring. Email notifications are appearing properly.

v1.3T Environmental Variables:
Device: Tarako v1.3T MOZ
BuildID: 20140404004001
Gaia: acd18bbd94ebfa534e252a24a75a0617e4b5d5ae
Gecko: 91a1b54da4a6
Version: 28.1
Firmware Version: sp8810
Status: REOPENED → RESOLVED
Closed: 10 years ago10 years ago
Resolution: --- → WORKSFORME
[Environment]
* Buri
Gaia      553da99ab09b6b894d9f95bb06b16b6e1ddbf0a1
Gecko     https://hg.mozilla.org/mozilla-central/rev/5b6e82e7bbbf
BuildID   20140414160205
Version   31.0a1
ro.build.version.incremental=eng.archermind.20131114.105818
ro.build.date=Thu Nov 14 10:58:33 CST 2013

* Tarako
Gaia      23488b1a45221c17e6a32fdd4c9d0fdbdcf2d021
Gecko     https://hg.mozilla.org/releases/mozilla-b2g28_v1_3t/rev/72055108f470
BuildID   20140414164002
Version   28.1
ro.build.version.incremental=eng.cltbld.20140414.200743
ro.build.date=Mon Apr 14 20:07:51 EDT 2014


[Reault]
All PASS
Status: RESOLVED → VERIFIED
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: