Re: nnimap versus tls

[Gaute B Strokkenes <gs234@cam.ac.uk>]

On 6 jul 2003, kai.grossjohann@gmx.net wrote:
> Gaute B Strokkenes <gs234@cam.ac.uk> 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 `#<killed 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!!