Re: [Mutt] #3266: mutt-1.5.19: Complete hang while sending mail
#3266: mutt-1.5.19: Complete hang while sending mail through SMTPS
----------------------+-----------------------------------------------------
Reporter: Darwish | Owner: brendan
Type: defect | Status: accepted
Priority: major | Milestone: 1.6
Component: SMTP | Version: 1.5.19
Resolution: | Keywords: smtps, gmail, hang
----------------------+-----------------------------------------------------
Comment(by Darwish):
Replying to [comment:4 brendan]:
> Actually, it tells me that mutt is waiting for gmail and gmail is
waiting for mutt. The only thing I can think of here is that somehow the
termination command (`.^M` in the trace) was not actually flushed to the
server. But reading over `tls_socket_write`, I can't see how this would
happen.
Here's a more verbose debugging. It's ''really'' level 5 now (with
passwords removed!). I hope it can help:
{{{
Mutt 1.5.19 started at Mon Jun 15 22:10:00 2009
.
Debugging at level 5.
Reading configuration file '/usr/local//etc/Muttrc'.
parse_attach_list: ldata = 0x8103b98, *ldata = (nil)
parse_attach_list: added */.* [9]
parse_attach_list: ldata = 0x8103b9c, *ldata = (nil)
parse_attach_list: added text/x-vcard [7]
parse_attach_list: added application/pgp.* [2]
parse_attach_list: ldata = 0x8103b9c, *ldata = 0x812d3c8
parse_attach_list: skipping text/x-vcard
parse_attach_list: skipping application/pgp.*
parse_attach_list: added application/x-pkcs7-.* [2]
parse_attach_list: ldata = 0x8103ba0, *ldata = (nil)
parse_attach_list: added text/plain [7]
parse_attach_list: ldata = 0x8103b9c, *ldata = 0x812d3c8
parse_attach_list: skipping text/x-vcard
parse_attach_list: skipping application/pgp.*
parse_attach_list: skipping application/x-pkcs7-.*
parse_attach_list: added message/external-body [4]
parse_attach_list: ldata = 0x8103ba4, *ldata = (nil)
parse_attach_list: added message/external-body [4]
Reading configuration file '/home/darwish/.muttrc'.
Using default IMAP port 143
Using default IMAPS port 993
mutt_alloc_color(): Color pairs used so far: 1
mutt_alloc_color(): Color pairs used so far: 2
mutt_alloc_color(): Color pairs used so far: 3
mutt_alloc_color(): Color pairs used so far: 4
mutt_alloc_color(): Color pairs used so far: 5
mutt_alloc_color(): Color pairs used so far: 6
mutt_alloc_color(): Color pairs used so far: 7
mutt_alloc_color(): Color pairs used so far: 8
mutt_alloc_color(): Color pairs used so far: 9
mutt_alloc_color(): Color pairs used so far: 10
mutt_alloc_color(): Color pairs used so far: 11
mutt_alloc_color(): Color pairs used so far: 12
Connected to imap.gmail.com:993 on fd=5
imap_cmd_step: grew buffer to 512 bytes
5< * OK Gimap ready for requests from 41.237.142.142 n10if10878618mue.15
IMAP queue drained
5> a0000 CAPABILITY^M
5< * CAPABILITY IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA XLIST CHILDREN
XYZZY
Handling CAPABILITY
5< a0000 OK Thats all she wrote! n10if10878618mue.15
IMAP queue drained
imap_authenticate: Using any available method.
SASL local ip: 192.168.1.243;58841, remote ip:209.85.135.111;993
External SSF: 128
SASL: No worthy mechs found
imap_auth_sasl: IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA XLIST CHILDREN
XYZZY unavailable
5> a0001 LOGIN "darwish.07@xxxxxxxxx" ...^M
5< a0001 OK darwish.07@xxxxxxxxx authenticated (Success)
IMAP queue drained
Communication encrypted at 128 bits
5> a0002 CAPABILITY^M
a0003 LIST "" ""^M
5< * CAPABILITY IMAP4rev1 UNSELECT LITERAL+ IDLE NAMESPACE QUOTA ID XLIST
CHILDREN X-GM-EXT-1
Handling CAPABILITY
5< a0002 OK Success
5< * LIST (\Noselect) "/" "/"
5< a0003 OK Success
IMAP queue drained
5> a0004 STATUS "[Gmail]/Drafts" (MESSAGES)^M
a0005 SELECT "Mine"^M
mboxcache: hcache uidvalidity 45, uidnext 13699
5< * STATUS "[Gmail]/Drafts" (MESSAGES 0)
mboxcache: hcache uidvalidity 8, uidnext 4668
[Gmail]/Drafts (UIDVALIDITY: 8, UIDNEXT: 4668) 0 messages, 0 recent, 0
unseen
Running default STATUS handler
5< a0004 OK Success
5< * FLAGS (\Answered \Flagged \Draft \Deleted \Seen)
Getting mailbox FLAGS
5< * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)]
Getting mailbox PERMANENTFLAGS
5< * OK [UIDVALIDITY 45]
Getting mailbox UIDVALIDITY
5< * 15 EXISTS
Handling EXISTS
cmd_handle_untagged: New mail in Mine - 15 messages total.
5< * 0 RECENT
5< * OK [UNSEEN 4]
5< * OK [UIDNEXT 13699]
Getting mailbox UIDNEXT
5< a0005 OK [READ-WRITE] Mine selected. (Success)
IMAP queue drained
Mailbox flags: [\Answered] [\Flagged] [\Draft] [\Deleted] [\Seen] [\*]
message.c:105: mutt_mktemp returns "/tmp/mutt-HOME-LAPTOP-1000-19256-0".
Updating progress: 0
5> a0006 UID FETCH 1:13698 (UID FLAGS)^M
5< * 1 FETCH (UID 12281 FLAGS (\Seen))
Handling FETCH
FETCH response ignored for this message
5< * 2 FETCH (UID 12400 FLAGS (\Seen))
Handling FETCH
FETCH response ignored for this message
5< * 3 FETCH (UID 12612 FLAGS (\Seen))
Handling FETCH
FETCH response ignored for this message
5< * 4 FETCH (UID 12704 FLAGS (\Seen))
Handling FETCH
FETCH response ignored for this message
5< * 5 FETCH (UID 12786 FLAGS (\Seen))
Handling FETCH
FETCH response ignored for this message
5< * 6 FETCH (UID 13679 FLAGS (\Seen))
Handling FETCH
FETCH response ignored for this message
5< * 7 FETCH (UID 13680 FLAGS (Old))
Handling FETCH
FETCH response ignored for this message
5< * 8 FETCH (UID 13681 FLAGS (Old))
Handling FETCH
FETCH response ignored for this message
5< * 9 FETCH (UID 13682 FLAGS (Old))
Handling FETCH
FETCH response ignored for this message
Updating progress: 10
5< * 10 FETCH (UID 13691 FLAGS (\Seen))
Handling FETCH
FETCH response ignored for this message
5< * 11 FETCH (UID 13692 FLAGS (\Seen))
Handling FETCH
FETCH response ignored for this message
5< * 12 FETCH (UID 13694 FLAGS (\Seen))
Handling FETCH
FETCH response ignored for this message
5< * 13 FETCH (UID 13695 FLAGS (\Seen))
Handling FETCH
FETCH response ignored for this message
5< * 14 FETCH (UID 13696 FLAGS (\Seen))
Handling FETCH
FETCH response ignored for this message
5< * 15 FETCH (UID 13697 FLAGS ())
Handling FETCH
FETCH response ignored for this message
5< a0006 OK Success
IMAP queue drained
Updating progress: 0
imap_open_mailbox: msgcount is 15
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_num_postponed: 0 postponed IMAP messages found.
mutt_index_menu[605]: Got op 97
5> a0007 STATUS "[Gmail]/Drafts" (MESSAGES)^M
5< * STATUS "[Gmail]/Drafts" (MESSAGES 0)
[Gmail]/Drafts (UIDVALIDITY: 8, UIDNEXT: 4668) 0 messages, 0 recent, 0
unseen
Running default STATUS handler
5< a0007 OK Success
IMAP queue drained
mutt_num_postponed: 0 postponed IMAP messages found.
send.c:1183: mutt_mktemp returns "/tmp/mutt-HOME-LAPTOP-1000-19256-1".
headers.c:47: mutt_mktemp returns "/tmp/mutt-HOME-LAPTOP-1000-19256-2".
send.c:976: mutt_mktemp returns "/tmp/mutt-HOME-LAPTOP-1000-19256-3".
Connected to smtp.gmail.com:465 on fd=6
6< 220 mx.google.com ESMTP s11sm1780675mue.41
6> EHLO HOME-LAPTOP.vodafone^M
6< 250-mx.google.com at your service, [41.237.142.142]
6< 250-SIZE 35651584
6< 250-8BITMIME
6< 250-AUTH LOGIN PLAIN
6< 250-ENHANCEDSTATUSCODES
6< 250 PIPELINING
SASL local ip: 192.168.1.243;33267, remote ip:209.85.135.111;465
External SSF: 128
External authentication name: darwish.07@xxxxxxxxx
6> AUTH LOGIN^M
6< 334 VXNlcm5hbWU6
mutt_sasl_cb_authname: getting authname for smtp.gmail.com:465
mutt_sasl_cb_pass: getting password for
darwish.07@xxxxxxxxx@smtp.gmail.com:465
...
6< 235 2.7.0 Accepted
SASL protection strength: 0
SASL protection buffer size: 65536
6> MAIL FROM:<darwish.07@xxxxxxxxx>^M
6< 250 2.1.0 OK s11sm1780675mue.41
6> RCPT TO:<darwish.07@xxxxxxxxx>^M
6< 250 2.1.5 OK s11sm1780675mue.41
Updating progress: 0
6> DATA^M
6< 354 Go ahead s11sm1780675mue.41
6> Date: Mon, 15 Jun 2009 22:10:22 +0300^M
Updating progress: 38
6> From: darwish.07@xxxxxxxxx^M
Updating progress: 65
6> To: darwish.07@xxxxxxxxx^M
Updating progress: 90
6> Subject: Test^M
Updating progress: 104
6> Message-ID: <20090615191022.GA19256@xxxxxxxxxxxxxxxxxxxx>^M
Updating progress: 162
6> MIME-Version: 1.0^M
Updating progress: 180
6> Content-Type: text/plain; charset=us-ascii^M
Updating progress: 223
6> Content-Disposition: inline^M
Updating progress: 251
6> User-Agent: Mutt/1.5.19 (2009-01-05)^M
Updating progress: 288
6> ^M
Updating progress: 289
6> Test mail^M
Updating progress: 299
6> .^M
6< 250 2.0.0 OK 1245092970 s11sm1780675mue.41
6> QUIT^M
mutt_free_body: Unlinking /tmp/mutt-HOME-LAPTOP-1000-19256-1.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: yes, darwish.07@xxxxxxxxx = darwish.07@xxxxxxxxx
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_addr_is_user: no, all failed.
mutt_index_menu[605]: Got op 97
5> a0008 STATUS "[Gmail]/Drafts" (MESSAGES)^M
5< * STATUS "[Gmail]/Drafts" (MESSAGES 0)
[Gmail]/Drafts (UIDVALIDITY: 8, UIDNEXT: 4668) 0 messages, 0 recent, 0
unseen
Running default STATUS handler
5< a0008 OK Success
IMAP queue drained
mutt_num_postponed: 0 postponed IMAP messages found.
send.c:1183: mutt_mktemp returns "/tmp/mutt-HOME-LAPTOP-1000-19256-4".
headers.c:47: mutt_mktemp returns "/tmp/mutt-HOME-LAPTOP-1000-19256-5".
send.c:976: mutt_mktemp returns "/tmp/mutt-HOME-LAPTOP-1000-19256-6".
Connected to smtp.gmail.com:465 on fd=6
6< 220 mx.google.com ESMTP n7sm4542221mue.28
6> EHLO HOME-LAPTOP.vodafone^M
6< 250-mx.google.com at your service, [41.237.142.142]
6< 250-SIZE 35651584
6< 250-8BITMIME
6< 250-AUTH LOGIN PLAIN
6< 250-ENHANCEDSTATUSCODES
6< 250 PIPELINING
SASL local ip: 192.168.1.243;43221, remote ip:209.85.135.109;465
External SSF: 128
External authentication name: darwish.07@xxxxxxxxx
6> AUTH LOGIN^M
6< 334 VXNlcm5hbWU6
mutt_sasl_cb_authname: getting authname for smtp.gmail.com:465
mutt_sasl_cb_pass: getting password for
darwish.07@xxxxxxxxx@smtp.gmail.com:465
6> ZGFyd2lzaC4wN0BnbWFpbC5jb20=^M
6< 334 UGFzc3dvcmQ6
6> TW9TIzI1Ny9UYSM=^M
6< 235 2.7.0 Accepted
SASL protection strength: 0
SASL protection buffer size: 65536
6> MAIL FROM:<darwish.07@xxxxxxxxx>^M
6< 250 2.1.0 OK n7sm4542221mue.28
6> RCPT TO:<darwish.07@xxxxxxxxx>^M
6< 250 2.1.5 OK n7sm4542221mue.28
Updating progress: 0
6> DATA^M
6< 354 Go ahead n7sm4542221mue.28
6> Date: Mon, 15 Jun 2009 22:10:46 +0300^M
Updating progress: 38
6> From: darwish.07@xxxxxxxxx^M
Updating progress: 65
6> To: darwish.07@xxxxxxxxx^M
Updating progress: 90
6> Subject: Test v2 .. test smtp^M
Updating progress: 120
6> Message-ID: <20090615191046.GB19256@xxxxxxxxxxxxxxxxxxxx>^M
Updating progress: 178
6> MIME-Version: 1.0^M
Updating progress: 196
6> Content-Type: text/plain; charset=us-ascii^M
Updating progress: 239
6> Content-Disposition: inline^M
Updating progress: 267
6> User-Agent: Mutt/1.5.19 (2009-01-05)^M
Updating progress: 304
6> ^M
Updating progress: 305
6> Test v2 .. test smtp^M
Updating progress: 326
6> ^M
Updating progress: 327
6> .6> ...Updating progress: 330
6> .^M
}}}
After exactly ''12 minutes'', mutts gets control back as usual and prints:
{{{
SMTP session failed: 451 4.4.2 Timeout - closing connection.
n7sm4542221mue.28
}}}
>
> By the way, the external authentication name bug is pretty harmless.
It's simply debug code using an uninitialized fixed-length buffer.
Thanks for the info.
--
Ticket URL: <http://dev.mutt.org/trac/ticket/3266#comment:5>
Mutt <http://www.mutt.org/>
The Mutt mail user agent