228237 - messages deleted while offline get turned into unread when going online

Status: RESOLVED FIXED

(MailNews Core :: Networking: IMAP, defect)

Description

[razl2]

User-Agent:       Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.6a) Gecko/20031029
Build Identifier: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.6a) Gecko/20031029

When I'm marking messages to be deleted while working offline, once reconnected,
those messages get remarked as unread and don't get deleted.  This behavior
cropped up in version 1.5 and exists in 1.6a.  1.4 works fine.

Reproducible: Always

Steps to Reproduce:
1.offline mozilla imap client
2.delete mails
3.reconnect to server
4. compact folders

Actual Results:  
Messages which were marked as deleted get remarked as unread.

Expected Results:  
deleted mails should be removed when you compact the folders.

Comment 1

[guanxi]

severity -> major

Comment 2

[David :Bienvenu]

Can I get an imap protocol log of a session where you do the steps to reproduce?

http://www.mozilla.org/quality/mailnews/mail-troubleshoot.html#imap

This works fine for me.  What happens if you don't do the compact? Does it work?
I have a theory that would explain this, if you're using the UW IMAP server that
comes with Red Hat 7.2, which rolls UID validity when you issue a compact. The
log will tell me if that's what's going on. However, it wouldn't explain why
this would work in 1.4 and not 1.5 or 1.6...

Comment 3

[razl2]

My appologies, the compact command was incorrect, it should have beeg get
messages command.

Usually I click the connect plug and mozilla doesn't always immediately sync
until I get messages.  In 1.4, all messages get deleted and then new ones get
pulled in.  In 1.5 or 1.6, new messages get brought in, however , the ones I had
previously marked as deleted ret remarked as unread instead of being deleted. 
Sorry for the mixup.

BTW, as an aside, I'm seeing quite a bit of degradation from 1.4 to 1.5 or 1.6.
 I'm seeing some LDAP issues to which I need to see if there is already a bug
filed for.

Comment 4

[Scott Renner]

Hmmm... I have this problem, I'm using UW IMAP 2002e, and I often see "compacting folders" when I get messages... I don't have the automatic compacting preference set, but it happens anyway. 

Comment 5

[David :Bienvenu]

Scott, that's just the expunging of the inbox on the imap server, not a compact
of a local store...unless you're using the imap delete model, where deleted
messages are shown with a big red X, when you open a folder or do get new
messages, we'll expunge the folder if there are more than 20 deleted but not
expunged messages.

Comment 6

[Mike Cowperthwaite]

xref bug 105238

Comment 7

[razl2]

(In reply to comment #0)
> User-Agent:       Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.6a) Gecko/20031029
> Build Identifier: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.6a) Gecko/20031029
> 
> When I'm marking messages to be deleted while working offline, once reconnected,
> those messages get remarked as unread and don't get deleted.  This behavior
> cropped up in version 1.5 and exists in 1.6a.  1.4 works fine.
> 
> Reproducible: Always
> 
> Steps to Reproduce:
> 1.offline mozilla imap client
> 2.delete mails
> 3.reconnect to server
> 4. compact folders
> 
> Actual Results:  
> Messages which were marked as deleted get remarked as unread.
> 
> Expected Results:  
> deleted mails should be removed when you compact the folders.

(In reply to comment #2)
> Can I get an imap protocol log of a session where you do the steps to reproduce?
> 
> http://www.mozilla.org/quality/mailnews/mail-troubleshoot.html#imap
> 
> This works fine for me.  What happens if you don't do the compact? Does it work?
> I have a theory that would explain this, if you're using the UW IMAP server that
> comes with Red Hat 7.2, which rolls UID validity when you issue a compact. The
> log will tell me if that's what's going on. However, it wouldn't explain why
> this would work in 1.4 and not 1.5 or 1.6...

Well. 1.7.2 is still really bad with this bug.  Itried using the above reference
to the protocol flags to obtain a protocol log, but when I set the env
variables,my log never got created.  Must the logfile exist?

I really need to get this fixed as 1.4.1 is way too old and I need some of the
other new features of the latest mozilla.

Comment 8

[David :Bienvenu]

please try a new trunk seamonkey or thunderbird build or a 1.0 branch
thunderbird build. I checked in a potential fix in bug 187145

Comment 9

[razl2]

(In reply to comment #8)
> please try a new trunk seamonkey or thunderbird build or a 1.0 branch
> thunderbird build. I checked in a potential fix in bug 187145

I tried Thunderbird version 0.8.  the same behavior happens there.  I finally
decided to swith my preferences to deleting mail into my trash folder (In
Thunderbird BTW).  This also had a wird behavior.  When iconnected from
off-line, my emails that I moved to the trash folder came back once the
connection was re-established.  After I emtied trash, some things did get
deleted.  This ones a bit trickier as I seem to be seeing a bit inconsistent
behavior.  Was your bug fix in 0.8?  Also, what is the Sea Monkey trunk? and how
do I access it?
Thanks (RAZ)

Comment 10

[razl2]

(In reply to comment #8)
> please try a new trunk seamonkey or thunderbird build or a 1.0 branch
> thunderbird build. I checked in a potential fix in bug 187145

I tried (what I think are) the latest releases of Mozilla and Thunderbird. 
Mozilla 1.8a5(2004110212) and Thunderbird .8+ (20041029).  Interestingly enough,
Thunderbird seems to be fixed, whereas Mozilla sill exhibits the same behaviour.
 Did your fix make it into Mozilla?

Comment 11

[David :Bienvenu]

the fix is in backend code, and was checked into both the trunk and the aviary
(tbird 1.0) branch. So perhaps it's still broken. Let me know if you see it
again on either app...

Comment 12

[razl2]

(In reply to comment #11)
> the fix is in backend code, and was checked into both the trunk and the aviary
> (tbird 1.0) branch. So perhaps it's still broken. Let me know if you see it
> again on either app...

OK, both apps are still broken.  here's what I've found, there's some kind of
timing issue going on with threads when you perform a reconnect.  My IMAP INBOX
was at 4000 messages (massive) when I tried the latest version of Thunderbird. 
Things worked fine until I hit roughly 3000 messages.  Then I noticed that a
portion of my messgaes ended up reverting back to their prior state.  By the
time I got my INBOX down to 1800, I can't replay any changes back.  They all
revert back to the state they were at when I initially offline the app.  Let me
know if there's any other data or debug testing I can do for you.  I seriosly
rely on offline capability, and this just aint cuttin it.

Comment 13

[David :Bienvenu]

You're suggesting that if you have a small inbox, it doesn't work? I don't know
how that could be related, but since I don't know what's going on, it might be
involved.

Again, a log file would be helpful. I don't know why the directions didn't work
for you. They work fine for others...the log file doesn't have to exist. As long
as you run the mozilla instance from the same shell that has the env vars set,
it should work fine.

Comment 14

[razl2]

(In reply to comment #13)
> You're suggesting that if you have a small inbox, it doesn't work? I don't know
> how that could be related, but since I don't know what's going on, it might be
> involved.
> 
> Again, a log file would be helpful. I don't know why the directions didn't work
> for you. They work fine for others...the log file doesn't have to exist. As long
> as you run the mozilla instance from the same shell that has the env vars set,
> it should work fine.
> 

Not necessarily saying a small INBOX is involved, I'm just trying to point out
the things I'm seeing.

I also noted that The connection speed I have seemed to exacerbate the problem.
 I exclussively  use a wireless connection, speeds are:
Home: 2.5MB
Work: 11MB
Train:  somewher in the KB range

It also seemed on slower connections this problem is more pronounced, hence
hitting into this timing issue since the connection seems to be slowing the
whole process down.

As for the log, the file gets created but is always of 0 size.  I would expect
all kinds of logging messages in this file after I startup Thunderbird if the
logging level is set to 5???

Comment 15

[David :Bienvenu]

yes, the log file would get huge. When you type setenv, what does it give as the
values of the two log vars?

Comment 16

[razl2]

(In reply to comment #15)
> yes, the log file would get huge. When you type setenv, what does it give as the
> values of the two log vars?

NSPR_LOG_FILE=/tmp/mozilla.log
NSPR_LOG_MODULES=protocol:5

I also notedt this goo too
_=NSPR_LOG_FILE

BTW, my log file is created, it's just zero length.  We are talking Thunderbird
here, right?  That is what I'm trying to test now and I'm assuming this log
modules thingy works for Tbird too.

Comment 17

[David :Bienvenu]

you substitute the appropriate protocol for "protocol", so it should be:

NSPR_LOG_MODULES=IMAP:5

Comment 18

[razl2]

Attachment: IMAP:5 log output when deleted messages revert back to original state

Comment 19

[razl2]

Attachment: Additional logfile

Comment 20

[razl2]

One thought.  1.4 doesn't have this problem, but all subsequent versions do. 
Would you like me to get a logfile of the 1.4 to see what it's supposed to do? 
Just a thought.

Comment 21

[razl2]

David, is there anything I can do to help move this along?

Comment 22

[razl2]

Check out big 123413.  This was an older bug I filed against Mozilla long ago an
d was fixed.  Is it possible that fix got accidentally backed out or overwritten?

Comment 23

[David :Bienvenu]

Sorry, I looked at that first log - it looks to me like many different messages
were marked read correctly, but that the very end, a handful had all their flags
cleared, including the read flag

54199:54203,54205:54215

I thought it was the case that marking messages read was never played back for
you - is it the case that only some of the message marking read is lost, in a
given session? In this particular log, it looks like we explicitly clear the
read flags (all flags, actually), instead of just losing playback operations, if
that makes sense. Do you do anything besides read and delete messages while
offline, e.g., do you label messages offline?

Comment 24

[David :Bienvenu]

the fix for bug 123413 is still in the code. Is it the case that none of your
deletes are ever played back?

Comment 25

[razl2]

(In reply to comment #23)
> Sorry, I looked at that first log - it looks to me like many different messages
> were marked read correctly, but that the very end, a handful had all their flags
> cleared, including the read flag
> 
> 54199:54203,54205:54215
> 
> I thought it was the case that marking messages read was never played back for
> you - is it the case that only some of the message marking read is lost, in a
> given session? In this particular log, it looks like we explicitly clear the
> read flags (all flags, actually), instead of just losing playback operations, if
> that makes sense. Do you do anything besides read and delete messages while
> offline, e.g., do you label messages offline?


I didn't think only a few were not played back correctly, I assumed it was all
but I never really experimented to see exactly what was happening.  Bootom line
is I read, delete, label and flag messages while I'm offline none of these
things seems to take when I do this and then try to replay once I'm back online
again.  BTW, I have to say that mozilla1.4 seems to work flawlessly in this area
and that is my current workaround to this issue.  Would another log of all these
events be useful?  Also, to cut down on the log size, I only ran the log during
the playback, not while I was offline.  Do you actully need to see the log of me
 executing the commands while offline as well as the playback?

Comment 26

[David :Bienvenu]

nothing happens when you're offline, as far as the log is concerned. The log you
attached showed us playing back dozens of offline actions to the server, so I
think many if not most actions are actually played back (it's hard to tell
unless you keep track, unfortunately :-( )

Comment 27

[razl2]

Thoughts on next steps?

Comment 28

[razl2]

(In reply to comment #24)
> the fix for bug 123413 is still in the code. Is it the case that none of your
> deletes are ever played back?

This is correct.  Whether I delete, read or label or flag, those changes seem to
get dropped and go back to the state the message was in just after I offlined
the tool.

Comment 29

[David :Bienvenu]

well, it's weird because the log you attached clearly shows us playing back
offline deletes, etc.

Can you try a simple test? set up logging, go offline, delete a message, go back
online (or shutdown and restart, online), and click get new mail. Does the
deleted message come back? If so, attach a protocol log of that...

Comment 30

[razl2]

Attachment: log of email reconnection where messages marked as deleted, change back to unread

Comment 31

[razl2]

(In reply to comment #29)
> well, it's weird because the log you attached clearly shows us playing back
> offline deletes, etc.
> 
> Can you try a simple test? set up logging, go offline, delete a message, go back
> online (or shutdown and restart, online), and click get new mail. Does the
> deleted message come back? If so, attach a protocol log of that...

OK, I deleted a single email while offline;  I exited the tool so I could
restart with logging enabled.  I connected once I got to my destination.  The
act of connecting took my email status back to the unread state.  I'm attaching
the log of this event.

Comment 32

[razl2]

David, anything interesting showing up in this latest log?

Comment 33

[David :Bienvenu]

it shows that we think the flags need to be all cleared, instead of set, for
those messages. What product and version did that last log come from? I did fix
a problem that could cause that...bug 187145. That fix went into thunderbird
1.0, and should be in seamonkey trunk builds...

Comment 34

[razl2]

(In reply to comment #33)
> it shows that we think the flags need to be all cleared, instead of set, for
> those messages. What product and version did that last log come from? I did fix
> a problem that could cause that...bug 187145. That fix went into thunderbird
> 1.0, and should be in seamonkey trunk builds...

I snagged a fairly recent version of thunderbird.  Version 1.0 (20050217)  Was
your fix in something newer?  Was your fix for a race condition?  I'm very sure
this is some kind of a race as every once in a great while, the code works. 
Howver, on mozilla1.4  it works almost all of the time, but I still see failures.

Comment 35

[David :Bienvenu]

That build has my fix in it. It wasn't a race condition, per se. Looking at your
log, it looks like you forwarded a message while offline, and deleted a few
other messages. Then, shutdown and restarted online. Do you use the imap delete
model, instead of deleting to the trash?

I tried that scenario as well on a 1.0 release build, and my debug trunk build,
and couldn't reproduce the problem. If you don't do the forwarding step, but
just delete a single message, does the problem still occur?

Comment 36

[razl2]

I checked out bug 187145 and this is the same bug as what I'm seeing.  The
problem  is that it looks like you fixed it back in 10/04 and the T'bird version
I tested on was from 2/17/05.  This version should have your fix.

Comment 37

[razl2]

(In reply to comment #35)
> That build has my fix in it. It wasn't a race condition, per se. Looking at your
> log, it looks like you forwarded a message while offline, and deleted a few
> other messages. Then, shutdown and restarted online. Do you use the imap delete
> model, instead of deleting to the trash?

Yes.  I use the delete model.

> 
> I tried that scenario as well on a 1.0 release build, and my debug trunk build,
> and couldn't reproduce the problem. If you don't do the forwarding step, but
> just delete a single message, does the problem still occur?

I'll check and see what happens with just a single delete.  At this point, I
think I better track down our imap server and version.  This may help you
reproduce the same scenario.  I'll also try deleting to trash and see how that
works.  I know I tried that in the past and saw the same failures.

Comment 38

[David :Bienvenu]

I doubt it has to do with the server, though it doesn't hurt to know. It might
have to do with running on linux, and it might require a specific set of steps...

Comment 39

[razl2]

OK, I tried using delete to trash this morning and the outcome was really
bizare.  Some things went to trash and stayed theree, other things which were
marked as read became marked as unread, and things I put a flag on had the flag
undone.  There was a lot happening there so i apologize for this scattered
information.  I'd prefer to focus on the delete mode first and resolve that. 
I'll be happy to help gather info on the delete to trash later.

Comment 40

[John Coonrod]

I see a similar thing in Mozilla 1.8b2. When I went back online, that status bar
says "Moving messages to trash" forever. I suggest that someone simply disable
the delete function when the program is offline, until somebody solves this.

Comment 41

[razl2]

David, I'm having trouble reproducing this failure on a single message like I
did before.  BTW, I have updated to the latest builds (or close to latest) so
that may be affecting this.  It still fails on deletes where I remove multiple
messages.  I can continue creating logs of this but I'm not sure if that will help.

I have a thought, I'm still real sure there's some kind of a timing issue.  Is
there a spot in the code once you reconnect (from being offline) where the
thread which reconnects to the server gets nailed by another reset thread which
takes everything back to the original state?  If you can find an area in the
code like this and can instrument thunderbird, I'd be happy to run that app and
try to get you  another log.  I'm not sure if we'll solve this issue with the
instrumentation  that's there now. Thoughts?

Comment 42

[David :Bienvenu]

I'm doubtful it's a threading issue, since this all happens on the ui thread, a
single thread.

I'm adding a bunch more logging to the offline code, and I'll check it in as
soon as I can, and let you know, and we'll go from there.

Comment 43

[David :Bienvenu]

Attachment: proposed fix

this could certainly explain some problems - the last operation on a given
message was the only one we remembered in the db.

Comment 44

[(not reading, please use [e-mail] instead)]

Comment on attachment 180378 [details] [diff] [review]
proposed fix

a=sspitzer for tbird 1.1a

Comment 45

[David :Bienvenu]

Attachment: add logging to help diagnose this problem

this adds a new PRLog module, IMAPOFFLINE, which logs all the offline
operations when all the offline ops are listed, and logs changes to the
existing offline operations.

Comment 46

[(not reading, please use [e-mail] instead)]

Comment on attachment 180401 [details] [diff] [review]
add logging to help diagnose this problem

a=sspitzer for tbird 1.1a

Comment 47

[David :Bienvenu]

Attachment: possible fix

I have to try this out, but I think this will fix the problem.

Comment 48

[David :Bienvenu]

Attachment: proposed fix

this fixes the case where the user does some send laters while offline, and
then when going online, selects a folder w/ offline events before offline
events have been played back for that folder. When getting offline ops, we were
crunching the value of the new flags with the current header's flags - in this
scenario, we didn't know what the flags were, so we were losing the flag
changes. 

I also fixed a problem where we would download headers for msgs we'd deleted
offline, because the code wasn't checking correctly if we had any offline
deletes or not.

Comment 49

[(not reading, please use [e-mail] instead)]

Comment on attachment 181915 [details] [diff] [review]
proposed fix

r/a=sspitzer for 1.1 tbird, assuming mscott gives the sr.

Comment 50

[David :Bienvenu]

*** Bug 241883 has been marked as a duplicate of this bug. ***