101828 - sending more than one piece of unsent mail fails when posting to sent mail folder

Status: VERIFIED FIXED

(MailNews Core :: Composition, defect)

Description

[Christopher Blizzard (:blizzard)]

This build is from the morning of Sept 25th, on the 0.9.4 branch.

1. Go offline
2. Compose mail and "Send Later"
3. Go online and send unsent messages

After the mail is sent and the mail is posted to the Sent mail folder I always
get a warning that the sending operating was successful but the save operation
failed.  I keep Sent mail on an IMAP/SSL server.

100% reproducable.  Happens every time.

Comment 1

[David :Bienvenu]

Did it send the message and then fail copying to the sent folder? Or did they
both succeed but you got an error anyway? I can't quite tell from your
description. Is your sent folder local or imap?

Comment 2

[grylchan]

Using sept 25 9.4 branch builds on linux 2.2

I couldn't reproduce the problem Chris. But I won't
lie to you in that I have never seen that error before.
I could just never reproduce on a conistent basis.

I have imap mail server. My sent folder is located on
my imap server.

Comment 3

[grylchan]

I reproduced it once but when I tried again, it didnt work. :-(

steps
1.login to imap server
2.make sure sent folder is located on the online imap server
3.go offline (dont download)
4.compose mesg, send later.
5.go back online (don't send unsent messages)
6.Click on any folder.
7.go offline again (dont download)
8.compose another mesg, send later.
9.go back online (don't send unsent mesgs)
10.Go to the menu: file|send unsent mesgs
   and send them
 result: i saw the error message once. I tried again and it
         wouldn't repeat.

Comment 4

[Christopher Blizzard (:blizzard)]

OK, here's how I can reproduce this issue 100% and you don't even have to go
offline to do it:

1. While online, I composed three pieces of email, all from [e-mail],
all to [e-mail].
2. Instead of using Send Now, use Send Later
3. Use File -> Send Unsent Messages

I get two failure messages about the copy to Sent mail failing.

After checking my email and the Sent mail folder on the imap server the mail was
successfully delivered but only one copy of the three that I sent out was
actually put into the Sent mail folder.

Sending one piece of mail at a time from the Sent mail folder always works for me.

Comment 5

[grylchan]

Uhh.. I couldn't reproduce the problem Chris.
I tried your steps and I didn't see the error.
The only slightly weird thing I saw is when I did
a 'get msg', only 2 of my 3 mesgs were delivered initially.
Had to do a 'get mesg' 2 more times in order to receive
the 3rd mesg. But 3 mesgs were copied to online sent folder
as expected.

Comment 6

[Christopher Blizzard (:blizzard)]

If I send two pieces of mail, I get one error.  If I send four, I get three
errors.  If I send one piece of mail with a From address from each account then
they don't fail.

Do you have a slow-ass connection like myself to test on?

Comment 7

[grylchan]

I did see the problem once with 9/26 linux branch builds on someone
else's computer/mail account. But when I tried it the 2nd time,
there was no error/error mesg.

Uhh the only slow ass connection I have is sera dial up from
home. :-)

I can try that. I'll talk to some of the mail qa people and
see if I can test it in their lab.

Comment 8

[Christopher Blizzard (:blizzard)]

OK, the copy is failing in |nsImapMailFolder::InitCopyState| with the assertion:

"move/copy already in progress"

It looks like we try to post the fcc while the last sent mail is still being
posted.  Here's the full stack trace:

(gdb) where
#0  nsDebug::Assertion (aStr=0x42a201bc "move/copy already in progress", 
    aExpr=0x42a201af "!m_copyState", aFile=0x42a1f880 "nsImapMailFolder.cpp", 
    aLine=5459) at nsDebug.cpp:195
#1  0x429b48ed in nsImapMailFolder::InitCopyState (this=0x8375800, 
    srcSupport=0x467ba080, messages=0x467be1c0, isMove=0, selectedState=0, 
    listener=0x467bccd8, msgWindow=0x0, allowUndo=0)
    at nsImapMailFolder.cpp:5459
#2  0x429b3a3c in nsImapMailFolder::CopyFileMessage (this=0x8375800, 
    fileSpec=0x467ba080, msgToReplace=0x0, isDraftOrTemplate=0, msgWindow=0x0, 
    listener=0x467bccd8) at nsImapMailFolder.cpp:5342
#3  0x44f7a241 in nsMsgCopy::DoCopy (this=0x44d453d0, aDiskFile=0x467ba080, 
    dstFolder=0x837581c, aMsgToReplace=0x0, aIsDraft=0, msgWindow=0x0, 
    aMsgSendObj=0x4670b420) at nsMsgCopy.cpp:304
#4  0x44f79daa in nsMsgCopy::StartCopyOperation (this=0x44d453d0, 
    aUserIdentity=0x422d2300, aFileSpec=0x467ba080, aMode=0, 
    aMsgSendObj=0x4670b420, 
    aSavePref=0x44ef2ce8 "imap://blizzard@localhost/Sent", aMsgToReplace=0x0)
    at nsMsgCopy.cpp:236
#5  0x44f71518 in nsMsgComposeAndSend::StartMessageCopyOperation (
    this=0x4670b420, aFileSpec=0x467ba080, mode=0, 
    dest_uri=0x484069c0 "imap://blizzard@localhost/Sent") at nsMsgSend.cpp:4230
#6  0x44f71346 in nsMsgComposeAndSend::MimeDoFCC (this=0x4670b420, 
    input_file=0x462b5078, mode=0, bcc_header=0x44fceac6 "", 
    fcc_header=0x44ebb760 "imap://blizzard@localhost/Sent", 
    news_url=0x477c5e70 "") at nsMsgSend.cpp:4196
#7  0x44f6f376 in nsMsgComposeAndSend::DoFcc (this=0x4670b420)
    at nsMsgSend.cpp:3311
#8  0x44f6f17d in nsMsgComposeAndSend::DoDeliveryExitProcessing (
    this=0x4670b420, aUri=0x438a09c4, aExitCode=0, aCheckForMail=0)
    at nsMsgSend.cpp:3253
#9  0x44f6f1d0 in nsMsgComposeAndSend::DeliverAsMailExit (this=0x4670b420, 
    aUrl=0x438a09c4, aExitCode=0) at nsMsgSend.cpp:3272
#10 0x44f6d23b in SendDeliveryCallback (aUrl=0x438a09c4, aExitCode=0, 
    deliveryType=nsMailDelivery, tagData=0x4670b420) at nsMsgSend.cpp:2850
#11 0x44f7f5df in nsMsgDeliveryListener::OnStopRunningUrl (this=0x467a5620, 
    aUrl=0x438a09c4, aExitCode=0) at nsMsgDeliveryListener.cpp:81
#12 0x41fd45f6 in nsUrlListenerManager::BroadcastChange (this=0x4670bbb0, 
    aUrl=0x438a09c4, notification=nsUrlNotifyStopRunning, aErrorCode=0)
    at nsUrlListenerManager.cpp:94
#13 0x41fd4689 in nsUrlListenerManager::OnStopRunningUrl (this=0x4670bbb0, 
    aUrl=0x438a09c4, aErrorCode=0) at nsUrlListenerManager.cpp:110
#14 0x420f6e1b in nsMsgMailNewsUrl::SetUrlState (this=0x438a09c4, 
    aRunningUrl=0, aExitCode=0) at nsMsgMailNewsUrl.cpp:114
#15 0x44f601e8 in nsSmtpProtocol::ProcessProtocolState (this=0x462e13b0, 
    url=0x438a09c4, inputStream=0x47710570, sourceOffset=405, length=54)
    at nsSmtpProtocol.cpp:1452
#16 0x420f354f in nsMsgProtocol::OnDataAvailable (this=0x462e13b0, 
    request=0x46221990, ctxt=0x438a09c4, inStr=0x47710570, sourceOffset=405, 
    count=54) at nsMsgProtocol.cpp:245
#17 0x40ad9413 in nsOnDataAvailableEvent::HandleEvent (this=0x8720d10)
    at nsStreamListenerProxy.cpp:178
#18 0x40ac597c in nsARequestObserverEvent::HandlePLEvent (plev=0x8720d10)
    at nsRequestObserverProxy.cpp:64
#19 0x401c734c in PL_HandleEvent (self=0x8720d10) at plevent.c:590
#20 0x401c7161 in PL_ProcessPendingEvents (self=0x80a59d8) at plevent.c:520
#21 0x401c93ee in nsEventQueueImpl::ProcessPendingEvents (this=0x80a59b0)
    at nsEventQueue.cpp:374
#22 0x410bf724 in event_processor_callback (data=0x80a59b0, source=6, 
    condition=GDK_INPUT_READ) at nsAppShell.cpp:169
#23 0x410bf303 in our_gdk_io_invoke (source=0x82bb768, condition=G_IO_IN, 
    data=0x82bb758) at nsAppShell.cpp:62
#24 0x40460f9e in g_io_unix_dispatch () at ../../../dist/include/nsCOMPtr.h:409
#25 0x40462773 in g_main_dispatch () at ../../../dist/include/nsCOMPtr.h:409
#26 0x40462d39 in g_main_iterate () at ../../../dist/include/nsCOMPtr.h:409
#27 0x40462eec in g_main_run () at ../../../dist/include/nsCOMPtr.h:409
#28 0x4037d333 in gtk_main () at ../../../dist/include/nsCOMPtr.h:409
#29 0x410bfd99 in nsAppShell::Run (this=0x80f35c8) at nsAppShell.cpp:349
#30 0x408866ad in nsAppShellService::Run (this=0x80fff50)
    at nsAppShellService.cpp:441
#31 0x080590a1 in main1 (argc=2, argv=0xbffff744, nativeApp=0x0)
    at nsAppRunner.cpp:1278
#32 0x08059d7f in main (argc=2, argv=0xbffff744) at nsAppRunner.cpp:1606
#33 0x405a8507 in __libc_start_main (main=0x8059b7c <main>, argc=2, 
    ubp_av=0xbffff744, init=0x80538ac <_init>, fini=0x8062008 <_fini>, 
    rtld_fini=0x4000dc14 <_dl_fini>, stack_end=0xbffff73c)
    at ../sysdeps/generic/libc-start.c:129

Comment 9

[David :Bienvenu]

My guess is that this has to do with some of the changes to the way message send
happens. -> JF

Comment 10

[Christopher Blizzard (:blizzard)]

Well, it appears that we attempt another message send before the copy to the
sent folder is complete.  What I'm trying to figure out is how that notification
is sent back to trigger the next message to be sent.

Should we be using the message copy service for this?  It serializes copies. 
Also I'm trying to figure out if moving the OnStopSending() notification can be
sent after the copy completes.  I suspect not since OnStopSending() is probably
for the smtp part of the transaction.  Anyway.  Looking more.

Comment 11

[David :Bienvenu]

I think Navin removed use of the copy service to fix some other problem. Cc'ing him.

Comment 12

[Navin Gupta]

There were some problems with editing and saving again drafts and templates,
so I worked with cavin on the issue. I can imagine because you have slow
connection copy is failing to complete before you want to copy the next 
message to same imap folder. You will have to clear the copystate 
ClearCopyState() before you can copy the next message. So the code that
interrupts copy and sends the next message should call ClearCopyState.
may have to deal with partially copied message. 

Comment 13

[David :Bienvenu]

JF, correct me if I'm wrong, but I imagine this is the way it should work if you
have, say, 3 messages in your outbox:

1. First message gets sent to smtp server, and copied to imap sent folder.
2. Then, Second message gets sent to smtp server, and copied to imap sent folder
3. Then, Third message gets sent to smtp server, and then copied to imap sent
folder.

If that's right, there's no way for the copies to coincide, because everything
is serialized.

Navin seems to be implying that there are separate processes, like this:

1st message gets sent and copied to the sent folder, and simultaneously, the
second and third messages are sent and copied to the sent folder.  I don't think
we should be interrupting any copies, no matter how slow the connection, so I'm
confused. My guess is that some state isn't getting cleared between the copies,
but it's not a timing issue.

Comment 14

[Jean-Francois Ducarroz]

Right, this is the way it (should) works

Comment 15

[grylchan]

Ok tried 9/26 commercial branch build on win98 computer with
a dial up modem (53k) in one of the labs.

I tried Chris's 2nd test:
 >1. While online, I composed three pieces of email, all from 
 >[e-mail],
 >all to [e-mail].
 >2. Instead of using Send Now, use Send Later
 >3. Use File -> Send Unsent Messages

 1st test: did it with 3 messages: I only saw 1 error message (not 2 like
           Chris saw),got all 3 mesgs in my inbox, but the strange thing
           was that only my 1st and 3rd message was copied to my 'sent
           mesgs' folder. The 2nd mesg was not copied.
 2nd test: tried with 4 messages: I only saw 1 error message (not 3 like
           Chris saw), got all 4 mesgs in my inbox, and only the 1st,
           2nd, and 4th message was copied to my 'sent mesgs' folder. The
           3rd mesg was not copied.

 3rd test: I tried Chris's original test case (go offline, do a send later,
           send it when go back online) and did not see any errors. It worked.
 4th test: Retried Chris's 2nd test case but this time with 2 mesgs.
           I did not see the error and mesgs were copied to sent folder
           unlike my previous first two test cases. I think this might
           have happened because i went offline and tried Chris's
           orignal test case?

hope this helps.

Comment 16

[Christopher Blizzard (:blizzard)]

Attachment: patch

Comment 17

[Christopher Blizzard (:blizzard)]

The patch I've attached listens for the end of the copy operation before
initiating processing the next message in the unsent mail queue.  Looking for
feedback, reviews, etc.

Comment 18

[Navin Gupta]

Comment on attachment 51179 [details] [diff] [review]
patch

looks like you have done the right thing, it should wait for copy to complete
r=naving

Comment 19

[David :Bienvenu]

you'll have to take the printfs out before checking in, of course. Also, it does
seem like the right thing to do; I'm very surprised it wasn't doing this before.
However, I don't see where you've attached yourself as a listener to the copy
operation. I'll look more closely at the patch.

Comment 20

[Christopher Blizzard (:blizzard)]

I'll remove the printfs if you want.  I was just copying the style in the rest
of the |SendOperationListener| class.  They are wrapped in NS_DEBUG and
apparently only the |OnStopCopy| method is called so it's not very verbose at all.

The listener is attached as part of |nsMsgComposeAndSend::CreateAndSendMessage|.
 The |mListener| member variable, which is passed into the function as an
|nsIMsgSendListener|, is QI'ed to an |nsIMsgCopyServiceListener|.  If it
supports that interface it's notified.

Personally, I thought it was a little messy from an API perspective but I didn't
write that particular piece of code. :)  If you want me to add a method to
|nsMsgComposeAndSend::CreateAndSendMessage| I'll be more than happy to do that
and fix all the callsites, too.

Comment 21

[David :Bienvenu]

Chris, thanks a lot for fixing this. I think I would like the printfs removed -
they just clutter up the code, especially if they're never invoked :-) I figured
the listener was QI'ed somewhere, but I just wanted to be sure. It's not my
favorite technique but it's pretty common practice throughout mozilla so I'd say
just leave it the way it is. Again, thanks for fixing this, sr=bienvenu.

Comment 22

[David :Bienvenu]

it just occurred to me - what happens if the user doesn't have a sent mail
folder specified? Also, we'd need to make sure this works if the sent mail
folder is local.

Comment 23

[Christopher Blizzard (:blizzard)]

If there's no sent mail folder specified ( there's no FCC folder in the code )
then OnStopCopy() is called by hand.  See the code in |nsMsgComposeAndSend::DoFcc|.

If the Sent folder is local this appears to work from testing.  I used Sent on
my local filesystem and several messages were sent out from my Unsent Messages
folder.

Comment 24

[Christopher Blizzard (:blizzard)]

Attachment: final patch

Comment 25

[Christopher Blizzard (:blizzard)]

Also see bug 102178 for a similar problem with online mail as well.

Comment 26

[grylchan]

changing qa to sheelar
but when the fix lands I'll check to see if I see
any problems related to offline.

Comment 27

[Christopher Blizzard (:blizzard)]

Fix checked into the trunk.  The long term fix should be to use the copy service
but naving is already dealing with that in another bug.

Also, if you guys want I can get this into the 0.9.4 branch as well.  This would
benifit the offline users, for sure.  It's been kicking my butt all over the place.

Comment 28

[grylchan]

adding Hong to cc list..

Comment 29

[grylchan]

Chris, David, anyone..

Just wondering if any of you can explain why it is sometimes
reproducible and sometimes not?

As you know I was trying to help verify the problem exists
and/or find some steps to reproduce but I couldn't
replicate consistently.

Is it connection speed? 

I am playing with 10-2 commercial
branch builds. For some reason, I can reproduce the
error everytime in 10-2 linux build (I couldn't before no
matter what I did) and yet I can't reproduce it in 10-2 windows build.
Both cases I've got high speed connection.

I'm using different mail accounts for win/linux testing but both 
are imap and using the same mail server. And they both were migrated
profiles.

I'd like any additional info just to help verify it's fixed.

thanks.

Comment 30

[Christopher Blizzard (:blizzard)]

I don't have any problems reproducing the problem. I have a slow connection and
my  saved mail on an IMAP/SSL server and all I have to do is try to send a few
unsent messages.  If your IMAP connection is fast enough, you won't see this
problem.

Comment 31

[Gervase Markham [:gerv]]

I think I've probably been seeing this when trying to send more than one bit of
mail at once on an always-on fast Intranet connection - so it's not just
blizzard :-)

Gerv

Comment 32

[Sheela Ravindran]

Chris,
Is this fix checked in only for trunk or branch too?  If not will this fix go
into branch as well? 

Comment 33

[Christopher Blizzard (:blizzard)]

Gerv, you might be tripping over the general bug with copying messages.  This is
just for sending later where it's a real problem.

Sheela, I would be more than happy to check this into the 0.9.4 branch for you.
 However, someone from Netscape who represents PDT has to give me the thumbs up
since that branch is under their control at the moment.

Comment 34

[Scott MacGregor]

I'll talk it over with PDT today and we'll see what we can do.
Ducarroz/naving/blizzard can you give me a risk assessment of what you thought
of the patch? It looked pretty straight forward to me after a cusory look over.

Comment 35

[Jaime Rodriguez, Jr.]

pls check it in to the branch - PDT+

Comment 36

[Scott MacGregor]

Sheela, I just checked blizzard's patch into the branch. Can you test this on
the branch builds tomorrow? 

Comment 37

[Sheela Ravindran]

Sure, I will run the test cases for both local as well as imap sent folder.  I
will update the bug as soon as I am done.  

Comment 38

[grylchan]

Using 10-4 commercial branch builds on NT 4.0, linux 2.2, mac 9.1
and mac OS 10.1:

Testing send later while offline:
 I don't see the 'saving to sent folder' error message and
 my mesgs were all saved to online sent folder.
 I tried both sending mail (that was composed offline)
 using 'send unsent mesgs' prompt and from the menu item
 'send unsent messages'. NO problems.

 Note I couldn't reproduce this error in prior builds except
      on linux. The 10-2 build I could consistently reproduce
      the error but when I tried the 10-4 build there was no error.
 

Comment 39

[Sheela Ravindran]

Tested both copying message to local sent folder as well as imap sent folder 
while sending the message.  
On linux, I got the copy to sent folder failure dialog. But after checking the 
folder the message was copied to the local sent folder. So the dlg should not 
have appeared.  But I was not able to reproduce this when I tried 2 more times I 
repeated the test.  
Mac and Windows worked fine. The copy of the message was succesful both to imap 
and sent local folder.
Branch Builds: 2001-10-04-05 win98, linux, mac.
Adding keyword vtrunk. Still needs verification on the trunk build.

Comment 40

[David :Bienvenu]

Was this ever checked into the branch? See bug 104443.

Comment 41

[Christopher Blizzard (:blizzard)]

Yeah, mscott said that he checked it in there.

Comment 42

[Scott MacGregor]

10/03/2001 18:25mscott%netscape.com mozilla/ mailnews/ compose/ src/
nsMsgSendLater.h 1.21.2.1 MOZILLA_0_9_4_BRANCH  5/1  Landing Bug # 101828 on the
branch. Sending more than one piece of unsent mail fails when posting to the
sent folder. 10/03/2001 18:25mscott%netscape.com mozilla/ mailnews/ compose/
src/ nsMsgSendLater.cpp 1.74.2.3 MOZILLA_0_9_4_BRANCH  44/4 

Comment 43

[Sheela Ravindran]

Removing keyword vtrunk 
Verified this on all using 2001-11-09-06 on win98, linux, mac 9.1
Does not fail to copy to sent imap or local folder sending unsent message. 

Comment 44

[Christopher Blizzard (:blizzard)]

Just FYI you will still see errors when sending unsent mail if you try to send
another piece of mail at the same time offline messages are being sent from a
normal compose window.  That's a different bug just in case someone tries to dup
to this one.