From mboxrd@z Thu Jan 1 00:00:00 1970 X-Msuck: nntp://news.gmane.io/gmane.emacs.gnus.general/53338 Path: main.gmane.org!not-for-mail From: Gaute B Strokkenes Newsgroups: gmane.emacs.gnus.general Subject: Re: nnimap versus tls Date: Sun, 06 Jul 2003 22:53:27 +0100 Organization: The Church of Emacs Sender: ding-owner@lists.math.uh.edu Message-ID: <873chjtj8o.fsf@cam.ac.uk> References: <87ptmfhxj6.fsf@cam.ac.uk> <84of0ab15z.fsf@lucy.is.informatik.uni-duisburg.de> <87k7axwef3.fsf@cam.ac.uk> <843chlyw19.fsf@lucy.is.informatik.uni-duisburg.de> <87adbrq0dy.fsf@cam.ac.uk> <84he5z4pne.fsf@lucy.is.informatik.uni-duisburg.de> NNTP-Posting-Host: main.gmane.org Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii X-Trace: main.gmane.org 1057528516 7693 80.91.224.249 (6 Jul 2003 21:55:16 GMT) X-Complaints-To: usenet@main.gmane.org NNTP-Posting-Date: Sun, 6 Jul 2003 21:55:16 +0000 (UTC) Original-X-From: ding-owner+M1882@lists.math.uh.edu Sun Jul 06 23:55:13 2003 Return-path: Original-Received: from malifon.math.uh.edu ([129.7.128.13]) by main.gmane.org with esmtp (Exim 3.35 #1 (Debian)) id 19ZHTU-0001zj-00 for ; Sun, 06 Jul 2003 23:55:12 +0200 Original-Received: from localhost ([127.0.0.1] helo=lists.math.uh.edu) by malifon.math.uh.edu with smtp (Exim 3.20 #1) id 19ZHSb-0004rn-00; Sun, 06 Jul 2003 16:54:17 -0500 Original-Received: from sclp3.sclp.com ([64.157.176.121]) by malifon.math.uh.edu with smtp (Exim 3.20 #1) id 19ZHSS-0004rh-00 for ding@lists.math.uh.edu; Sun, 06 Jul 2003 16:54:08 -0500 Original-Received: (qmail 64926 invoked by alias); 6 Jul 2003 21:54:08 -0000 Original-Received: (qmail 64921 invoked from network); 6 Jul 2003 21:54:08 -0000 Original-Received: from mta06-svc.ntlworld.com (62.253.162.46) by sclp3.sclp.com with SMTP; 6 Jul 2003 21:54:08 -0000 Original-Received: from belldandy ([81.100.93.186]) by mta06-svc.ntlworld.com (InterMail vM.4.01.03.37 201-229-121-137-20020806) with ESMTP id <20030706215406.TMYK16215.mta06-svc.ntlworld.com@belldandy> for ; Sun, 6 Jul 2003 22:54:06 +0100 Original-Received: from gs234 by belldandy with local (Exim 3.36 #1 (Debian)) id 19ZHRo-0007wi-00 for ; Sun, 06 Jul 2003 22:53:28 +0100 Mail-Copies-To: never Original-To: ding@gnus.org Face: iVBORw0KGgoAAAANSUhEUgAAADAAAAAwBAMAAAClLOS0AAAAG1BMVEWWWBTly7aGMwb+/vz9 +ffIilb///+yaCxNCwHGVC3gAAACU0lEQVR4nF2TQWvjMBBGVUGwj3WxaY/aAWNfi0zuwZPuHp0Q ob079OwYjHrsChb0s3dGctJ0ddTzm9F8lsR7WiNiWWL/flviul9Uh0NR4vY/gJUxJjOEtt/AubBy UsotRfH2DbxWE0hom3w5XJUEKis9hACt2hR4B86VDOtqTNHfgeEGvLiUN7Ddze26Dx6y1CUa+ygo NwFQm0N/BeMzCZAtNIoQrd9EhcH5mWpnztB8ZpJBlH23jaAbuE4EhZ2Bam0TeJ0DRMCKVP6CegWk q4z2TVFUx0946FOPcSe9ELE3rSHAj15rBuddS0C4BGyAutfpVAQkKdZOQiwMMIHxlUDrgeej5Ns7 I/ccSWNBLda1XwYBEG1Qswy1yXJf879nA4cjkNI0H+FzoUyuRodPA5eqZwFONG34i30ccOxeKFUy flNe1szqsgLdvXwKCj6zjTXODHV9M46gZPCLlYKCGTYO8S0aOAvJzRfD0w+1XcGIsxLUw/sYl5sM 9n0yjkoSUDOByrijwRRiAq13NhqLJYB3ACazrgN2bIwanyJQKXhHAJPRPQruEaCJP2Shy4DJ2As+ FQjJZH7AZIy6w0pQiiRYAh8nTEZHYDfRqSDeB5OXq4EEcAC4NocvoBl4+n1cyl54nyLRNA3iIwRP wNGFOK1g1Gz8jNfaCjdtqJLm2LXuqMc+50cDIJQpr6X0OHa4X58ULAw03QbRd7GUiG/K04mj0bNB xQhwJkEsJiZ1Bbgb6CnF79cBE+jwF91qniOCP3fghUFKxOShjIATw/wOfIQTg39LpFHtxhlKywAA AABJRU5ErkJggg== User-Agent: Gnus/5.1003 (Gnus v5.10.3) Emacs/21.3 (gnu/linux) Precedence: bulk Xref: main.gmane.org gmane.emacs.gnus.general:53338 X-Report-Spam: http://spam.gmane.org/gmane.emacs.gnus.general:53338 On 6 jul 2003, kai.grossjohann@gmx.net wrote: > Gaute B Strokkenes writes: > >> Having thought about this for a bit, I suspect that this is some >> sort of timing problem. I think that when gnus sends the LOGOUT >> command it does not hang around and wait for the server to say >> goodbye, but closes the connection of its own accord. If gnus >> kills the connection by first killing (process-buffer proc) and >> _then_ removes the process proper (and the filter, >> imap-arrival-filter) then the possibility exists that the final bit >> of chit-chat from the imap server ends up being processed after the >> buffer has been killed, but before the filter has been removed. >> This would cause the filter to throw an error, like we see. The >> timing dependence would also account for the intermittent nature of >> this bug. > > Very good analysis, IMHO. There are two instances of > (imap-send-command "LOGOUT") in imap.el -- should they be > (imap-send-command-wait "LOGOUT") instead? > > Do you want to try to see if that helps? I looked at that, but it seems like a dead end. Those instances are only called when trying/failing to use other streams. However, I added lots of debugging goop to imap.el: Index: imap.el =================================================================== RCS file: /usr/local/cvsroot/gnus/lisp/imap.el,v retrieving revision 6.52 diff -u -r6.52 imap.el --- imap.el 20 Apr 2003 13:44:27 -0000 6.52 +++ imap.el 6 Jul 2003 21:39:57 -0000 @@ -136,6 +136,14 @@ ;;; Code: +(defun gs234-debug (str) + (with-current-buffer (get-buffer-create imap-log-buffer) + (imap-disable-multibyte) + (buffer-disable-undo) + (goto-char (point-max)) + (insert str) + (insert "\n"))) + (eval-when-compile (require 'cl)) (eval-and-compile (autoload 'base64-decode-string "base64") @@ -529,7 +537,10 @@ (not (string-match "failed" response)))) (setq done process) (if (memq (process-status process) '(open run)) - (imap-send-command "LOGOUT")) + (progn + (gs234-debug (format "async close!")) + (imap-send-command "LOGOUT"))) +; (imap-send-command-wait "LOGOUT"))) (delete-process process) nil))))) done)) @@ -593,7 +604,10 @@ (not (string-match "failed" response)))) (setq done process) (if (memq (process-status process) '(open run)) - (imap-send-command "LOGOUT")) + (progn + (gs234-debug "async close!") + (imap-send-command "LOGOUT"))) +; (imap-send-command-wait "LOGOUT"))) (delete-process process) nil))))) done)) @@ -995,12 +1009,15 @@ (if (null (let ((imap-stream stream)) (imap-open-1 (current-buffer)))) (progn + (gs234-debug (format "kb1: killing buffer `%s'" + (current-buffer))) (kill-buffer (current-buffer)) (message "imap: Reconnecting with stream `%s'...failed" stream)) ;; We're done, kill the first connection (imap-close buffer) + (gs234-debug (format "kb2: killing buffer `%s'" buffer)) (kill-buffer buffer) (rename-buffer buffer) (message "imap: Reconnecting with stream `%s'...done" @@ -1071,10 +1088,15 @@ (with-current-buffer (or buffer (current-buffer)) (when (imap-opened) (condition-case nil - (imap-send-command-wait "LOGOUT") + (progn + (gs234-debug "imap: closing...") + (imap-send-command-wait "LOGOUT") + (gs234-debug "imap: ...closing now done")) (quit nil))) (when (and imap-process (memq (process-status imap-process) '(open run))) + (gs234-debug (format "imap: post-closure deletion of process `%s'" + imap-process)) (delete-process imap-process)) (setq imap-current-mailbox nil imap-current-message nil @@ -1739,11 +1761,16 @@ tag))) (defun imap-wait-for-tag (tag &optional buffer) +; (message "imap: waiting for tag `%s'" tag) (with-current-buffer (or buffer (current-buffer)) + (gs234-debug (format "imap: START wait for tag `%s'" tag)) + (gs234-debug (format "imap: imap-reached-tag is already: `%s'" + imap-reached-tag)) (let (imap-have-messaged) (while (and (null imap-continuation) (memq (process-status imap-process) '(open run)) (< imap-reached-tag tag)) + (gs234-debug "imap: going through body of loop") (let ((len (/ (point-max) 1024)) message-log-max) (unless (< len 10) @@ -1756,11 +1783,17 @@ 1000))))) (when imap-have-messaged (message "")) + (gs234-debug (format "imap: END wait for tag `%s'" tag)) + (gs234-debug (format "imap: imap-reached-tag is now: `%s'" imap-reached-tag)) + (gs234-debug (format "imap: imap-continuation is now: `%s'" imap-continuation)) + (gs234-debug (format "imap: (process-status imap-process) is now: `%s'" + (process-status imap-process))) (and (memq (process-status imap-process) '(open run)) (or (assq tag imap-failed-tags) - (if imap-continuation - 'INCOMPLETE - 'OK)))))) + (progn + (if imap-continuation + 'INCOMPLETE + 'OK))))))) (defun imap-sentinel (process string) (delete-process process)) @@ -1780,6 +1813,9 @@ (defun imap-arrival-filter (proc string) "IMAP process filter." + (gs234-debug (format "IAF: trying to grab buffer `%s', proc `%s'\n" + (process-buffer proc) + proc)) (with-current-buffer (process-buffer proc) (goto-char (point-max)) (insert string) @@ -1796,6 +1832,7 @@ (narrow-to-region (point-min) end) (delete-backward-char (length imap-server-eol)) (goto-char (point-min)) + (gs234-debug (format "IAF: imap-state is `%s'" imap-state)) (unwind-protect (cond ((eq imap-state 'initial) (imap-parse-greeting)) @@ -1803,6 +1840,7 @@ (eq imap-state 'nonauth) (eq imap-state 'selected) (eq imap-state 'examine)) + (gs234-debug "IAF: punting on imap-parse-response...") (imap-parse-response)) (t (message "Unknown state %s in arrival filter" A typical snippet from *imap-log* : imap: closing... 6 LOGOUT imap: START wait for tag `6' imap: imap-reached-tag is already: `5' imap: going through body of loop imap: going through body of loop imap: going through body of loop imap: going through body of loop imap: going through body of loop imap: going through body of loop imap: END wait for tag `6' imap: imap-reached-tag is now: `5' imap: imap-continuation is now: `nil' imap: (process-status imap-process) is now: `exit' imap: ...closing now done IAF: trying to grab buffer `#', proc `imap<1>' I think the problem is that imap-wait-for-tag is not doing its job properly in all circumstances. Specifically looking at the loop in imap-wait-for-tag, we loop until we get the tag we're waiting for, or until (process-status imap-process) is neither 'run nor 'open (or imap-continuation is non-nil, whatever that is...). Inside the loop, we call accept-process-output to take care of business. I believe that what is going on is that in one iteration of the loop, we receive the server's last bit of output after accept-process-output has returned, but before we test the loop condition. That way, (process-status imap-process) will be 'exit; but there will still be output waiting for us that we haven't taken care of yet. Everything will appear to work swimmingly until Emacs is about to idle, and it checks for process output again. Or so I think. Unless I'm missing something, the documentation in the elisp manual is not too specific about the semantics of subprocesses... -- Gaute Strokkenes http://www.srcf.ucam.org/~gs234/ My BIOLOGICAL ALARM CLOCK just went off.. It has noiseless DOZE FUNCTION and full kitchen!!