<<< Date Index >>>     <<< Thread Index >>>

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