1004137 - [email] Absolute positioned virtual list regression: Refresh-synced folder not showing newly added message outside date range

Status: RESOLVED FIXED

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

Description

[mkruml]

Attachment: email.txt

Description:
If a file is moved into the Junk or Drafts folder in an ActiveSync account on the server, the file will not sync properly on the device. The file will disappear until the folder is navigated to a second time.

Prerequisite: Have a hotmail account with multiple files in folders

Repro Steps:
1) Update a Open_C to BuildID: 20140430000201
2) On PC and DUT, set up/log into the hotmail account (ActiveSync) and navigate to the Inbox on both
3) On the PC, move a file from the Inbox into the Junk folder, then manually sync the inbox on the DUT to verify the move.
4) On the device, navigate to the Junk folder and manually sync.

Actual:
The moved file does not appear. Device has not synced from server properly. If the user then navigates to Inbox and back to Junk, the file will appear.

Expected:
The list of files in the folder always matches that on the server

1.4 Environmental Variables:
Device: Open_C 1.4 MOZ
BuildID: 20140430000201
Gaia: 81e97c3ca58be0487292011bc59efa4cebab30be
Gecko: 123485e733d5
Version: 30.0
Firmware Version: P821a10-eng_20140410

Notes: Also occurs on Buri 1.4

1.4 Environmental Variables:
Device: Buri 1.4 MOZ
BuildID: 20140430000201
Gaia: 81e97c3ca58be0487292011bc59efa4cebab30be
Gecko: 123485e733d5
Version: 30.0
Firmware Version: v1.2-device.cfg

Note: Does not occur on Buri 1.3

1.3 Environmental Variables:
Device: Buri 1.3 MOZ
BuildID: 20140429024001
Gaia: caab7a78f0c04913f48a3051259663ee85625906
Gecko: f84a8ffbc552
Version: 28.0
Firmware Version: v1.2-device.cfg

Repro frequency: 66-100%
Link to failed test case: https://moztrap.mozilla.org/manage/case/4360/
See attached: logcat: email.txt

Comment 1

[Jason Smith [:jsmith]]

Exactly what happens on 1.3?

Comment 2

[Pi Wei Cheng [:piwei] (inactive)]

On Buri 1.3, emails moved from Inbox to Junk via PC are synced and displayed correctly on Buri device. Issue not reproducible.

Tested on:
Device: Buri 1.3 MOZ
BuildID: 20140501024001
Gaia: 667539f1ed4becc45b182a5f1046221d3eeb9e7c
Gecko: 4b68615ea3e5
Version: 28.0
Firmware Version: v1.2-device.cfg

Comment 3

[Jason Smith [:jsmith]]

Andrew - Is this a bug or expected behavior?

Comment 4

[Andrew Sutherland [:asuth] (he/him)]

This is a complicated one if my hypothetical scenario based on the log is correct.  Basically, I think this is happening:
- Junk folder loaded, it has 3 messages in it.
- sync triggered
- 1 new message synchronized, but it is older than the oldest message currently displayed, so no splice notification is generated nor is headerCount updated.
- The front-end hears the completion notification.  atBottom is now false, but slice.items.length and slice.headerCount are still 3.

In the pre-bug 796474 version, we still would not get an explicit splice on this (because we never grow into the past unless we're not at our desiredHeaders level; this logic should not have changed).  But we would explicitly trigger onScroll, and onScroll would explicitly check atBottom.  That would trigger a call to requestGrowth and then we get to see the message.

I think the easiest and lowest risk fix is for us to move the .headerCount update up above the range-checking that uses "continue" to short-circuit the loop to skip the message.  I think we can get the desired low-level test coverage from test_folder_storage.js.

I'll work up a fix.

Comment 5

[Andrew Sutherland [:asuth] (he/him)]

Attachment: update the slice headerCount even when the header is not added to the slice

My hypothesis was correct.  I reproduced the problem on a device by adding a message older than the current messages in a folder (INTERNALDATE-wise) and refreshing.  The logcat shows we know about the new header but the UI does not update.

The GELAM PR has 2 commits: a test that fails without the fix, and then the fix.  When installed to gaia, things are happy.  I'll squash for landing.

To reduce the review burden, I'm including logcat traces below which I assert obviate the need for manual testing.

=== Current trunk (without patch):
05-05 02:10:52.581 I/Gecko   ( 1082): WLOG: syncDateRange: 631152000000 null
05-05 02:10:52.581 I/Gecko   ( 1082): WLOG: Skewed DB lookup. Start:  631152000000 Mon, 01 Jan 1990 00:00:00 GMT End:  null null
05-05 02:10:52.951 I/Gecko   ( 1082): WLOG: searchargs:  NOT DELETED SINCE 1-Jan-1990
05-05 02:10:53.121 I/Gecko   ( 1082): WLOG: SERVER UIDS 3 60
05-05 02:10:53.491 I/Gecko   ( 1082): WLOG:   new fetched, header processing, INTERNALDATE:  02-May-2014 03:16:42 +0000
05-05 02:10:53.661 I/Gecko   ( 1082): WLOG: FETCHED 0 known id 1 known srvid 10375 actual id 10374
05-05 02:10:53.681 I/Gecko   ( 1082): WLOG: FETCHED 1 known id 0 known srvid 10374 actual id 10375
05-05 02:10:53.691 I/Gecko   ( 1082): WLOG: Sync Completed! null days 3 messages synced
05-05 02:10:53.701 I/Gecko   ( 1082): WLOG: folder message count 3 dbCount 3 syncedThrough null oldest known 1399000602000
05-05 02:10:53.811 I/GeckoDump( 1082): LOG: message_list complete: 2 items of 2 alleged known headers. canGrow: false

=== With fix:
05-05 02:12:31.451 I/Gecko   ( 1147): WLOG: syncDateRange: 631152000000 null
05-05 02:12:31.461 I/Gecko   ( 1147): WLOG: Skewed DB lookup. Start:  631152000000 Mon, 01 Jan 1990 00:00:00 GMT End:  null null
05-05 02:12:35.111 I/Gecko   ( 1147): WLOG: searchargs:  NOT DELETED SINCE 1-Jan-1990
05-05 02:12:35.411 I/Gecko   ( 1147): WLOG: SERVER UIDS 4 60
05-05 02:12:35.831 I/Gecko   ( 1147): WLOG:   new fetched, header processing, INTERNALDATE:  01-May-2014 01:31:48 +0000
05-05 02:12:36.111 I/Gecko   ( 1147): WLOG: FETCHED 0 known id 1 known srvid 10375 actual id 10374
05-05 02:12:36.131 I/Gecko   ( 1147): WLOG: FETCHED 1 known id 0 known srvid 10374 actual id 10375
05-05 02:12:36.131 I/Gecko   ( 1147): WLOG: FETCHED 2 known id 2 known srvid 10376 actual id 10376
05-05 02:12:36.151 I/Gecko   ( 1147): WLOG: Sync Completed! null days 4 messages synced
05-05 02:12:36.161 I/Gecko   ( 1147): WLOG: folder message count 4 dbCount 4 syncedThrough null oldest known 1398907908000
05-05 02:12:36.261 I/GeckoDump( 1147): LOG: message_list complete: 3 items of 4 alleged known headers. canGrow: false
05-05 02:12:36.561 I/Gecko   ( 1147): WLOG: queueOp 3 downloadBodies
05-05 02:12:36.571 I/GeckoDump( 1147): LOG: VSCROLL scrollTop: 0, RECALCULATE: 0, 0
05-05 02:12:36.571 I/Gecko   ( 1147): WLOG: runOp(do: {"type":"downloadBodies","longtermId":"3/4","lifecycle":"do","localStatus":"done","serverStatus":"doing","tryCount":0,"humanOp":"downloadBodies","messages":[{"s)
05-05 02:12:36.661 I/GeckoDump( 1147): LOG: message_list loadNextChunk growing 1 (will get boosted to 15!) to 4 items out of 4 alleged known
05-05 02:12:37.121 I/Gecko   ( 1147): WLOG: runOp_end(do: {"type":"downloadBodies","longtermId":"3/4","lifecycle":"do","localStatus":"done","serverStatus":"doing","tryCount":0,"humanOp":"downloadBodies","messages":[{"s)
05-05 02:12:37.121 I/Gecko   ( 1147): 
05-05 02:12:37.231 I/GeckoDump( 1147): LOG: message_list complete: 4 items of 4 alleged known headers. canGrow: false

Comment 6

[Andrew Sutherland [:asuth] (he/him)]

Clearing regression window request; this was absolutely a new thing with bug 796474.

Comment 7

[Andrew Sutherland [:asuth] (he/him)]

While investigating an ActiveSync issue I also was able to induce an ignoreHeaders-related edge-case I was worried about during the original investigation.  There's a test for that as the third commit and a fix in the fourth commit now.  And here are the logs from b2g-desktop testing:

=== Bad Log
LOG: pushCard for type: message_list
WLOG: We want a filter of one week
WLOG: Sync completed: added 75, changed 0, deleted 0
WLOG: Sync Completed! 75 messages synced
LOG: message_list complete: 15 items of 0 alleged known headers. canGrow: false
LOG: VSCROLL scrollTop: 0, RECALCULATE: 0, 0

=== Good log
LOG: pushCard for type: message_list
WLOG: We want a filter of one week
WLOG: Sync completed: added 75, changed 0, deleted 0
WLOG: Sync Completed! 75 messages synced
LOG: message_list complete: 15 items of 75 alleged known headers. canGrow: false
LOG: message_list loadNextChunk growing 15 to 30 items out of 75 alleged known
LOG: message_list complete: 30 items of 75 alleged known headers. canGrow: false

Comment 8

[James Burke [:jrburke]]

Comment on attachment 8417195 [details] [review]
update the slice headerCount even when the header is not added to the slice

Discussed in IRC, and tried on device with activesync.

Comment 9

[Andrew Sutherland [:asuth] (he/him)]

== landed on master:
https://github.com/mozilla-b2g/gaia-email-libs-and-more/pull/303
https://github.com/mozilla-b2g/gaia-email-libs-and-more/commit/1047088042ae8d2845a0f117fb1c0c9f938ec382

https://github.com/mozilla-b2g/gaia/pull/19007
https://github.com/mozilla-b2g/gaia/commit/e51f41c910e5d27953f256a293cd0e9036359e33

== landed on v1.4:
https://github.com/mozilla-b2g/gaia/pull/19010
https://github.com/mozilla-b2g/gaia/commit/bac831d2ebc567f0939e41fbd8a4c15ef183b954