nnimap versus tls

nnimap versus tls

[Gaute B Strokkenes]

I didn't have much luck with this request in gnu.emacs.gnus; perhaps
someone here can help me?

I have one nnimap server and two imap mail-sources (one of which is
the same server as the nnimap server).  Everything works hunky-dory
until I add :stream tls to either or both of the imap mail-sources.
Everything works fine for a while, but eventually I get an error with
a backtrace that looks like this:

--8<--
Debugger entered--Lisp error: (error "Selecting deleted buffer")
  imap-arrival-filter(#<process imap<1>> "* BYE kern.srcf.societies.cam.ac.uk IMAP4rev1 server terminating connection^M\n6 OK LOGOUT completed^M\n*** Received corrupted data(-9) - server has terminated the connection abnormally\n")
  delete-process(#<process imap<2>>)
  imap-close(#<buffer  *imap source*>)
  mail-source-fetch-imap((imap :server "imap.hermes.cam.ac.uk" :mailbox "mail/limbo" :predicate "UNDELETED" :password "xxx" :stream tls) #[(file orig-file) "B.CD.	.?...E	F\"G%." [file orig-file nnmail-split-incoming nnml-save-mail nil nnmail-get-split-gr.oup (imap :server "imap.hermes.cam.ac.uk" :mailbox "mail/limbo" :predicate "UNDELETED" :password "xxx" :stream tls) nnml-active-number] 7])
  mail-source-fetch((imap :server "imap.hermes.cam.ac.uk" :mailbox "mail/limbo" :predicate "UNDELETED" :password "xxx" :stream tls) #[(file orig-file) "B.CD.	.?...E	F\"G%." [file orig-file nnmail-split-incoming nnml-save-mail nil nnmail-get-split-g.roup (.imap :server "imap.hermes.cam.ac.uk" :mailbox "mail/limbo" :predicate "UNDELETED" :password "xxx" :stream tls) nnml-active-number] 7])
  nnmail-get-new-mail(nnml nnml-save-nov "~/Mail/" nil)
  nnml-request-scan(nil "")
  gnus-request-scan(nil (nnml ""))
  gnus-read-active-file-1((nnml "") nil)
  gnus-read-active-file()
  gnus-group-get-new-news(nil)
  call-interactively(gnus-group-get-new-news)
--8<--

[Note that I have replaced my password with "xxx" in the backtrace.]
[The backtrace also contains control characters/whatnot, these will be
likely be munged when I post.]

I really don't know how to debug this at all, so I'm hoping someone
can help me...

-- 
Big Gaute                               http://www.srcf.ucam.org/~gs234/
I think my CAREER is RUINED!!

Re: nnimap versus tls

[Gaute B Strokkenes]

On 19 mai 2003, gs234@cam.ac.uk wrote:
> I didn't have much luck with this request in gnu.emacs.gnus; perhaps
> someone here can help me?
>
> I have one nnimap server and two imap mail-sources (one of which is
> the same server as the nnimap server).  Everything works hunky-dory
> until I add :stream tls to either or both of the imap mail-sources.
> Everything works fine for a while, but eventually I get an error
> with a backtrace that looks like this:
>
> --8<--
> Debugger entered--Lisp error: (error "Selecting deleted buffer")

[Snip]

> I really don't know how to debug this at all, so I'm hoping someone
> can help me...

I haven't been able to get any further with this since May.  Surely
there is someone who can at least give some advice on how to debug
this?

-- 
Big Gaute                               http://www.srcf.ucam.org/~gs234/
YOU!!  Give me the CUTEST, PINKEST, most charming little
 VICTORIAN DOLLHOUSE you can find!!  An make it SNAPPY!!

Re: nnimap versus tls

[Kai Großjohann]

Gaute B Strokkenes <gs234@cam.ac.uk> writes:

> --8<--
> Debugger entered--Lisp error: (error "Selecting deleted buffer")
>   imap-arrival-filter(#<process imap<1>> "* BYE kern.srcf.societies.cam.ac.uk IMAP4rev1 server terminating connection^M\n6 OK LOGOUT completed^M\n*** Received corrupted data(-9) - server has terminated the connection abnormally\n")
>   delete-process(#<process imap<2>>)

It seems that Gnus isn't expecting the server to close the
connection, err, unexpectedly.

Or am I misinterpreting this?
-- 
~/.signature

Re: nnimap versus tls

[Gaute B Strokkenes]

On 4 jul 2003, kai.grossjohann@gmx.net wrote:
> Gaute B Strokkenes <gs234@cam.ac.uk> writes:
>
>> --8<-- Debugger entered--Lisp error: (error "Selecting deleted
>> buffer") imap-arrival-filter(#<process imap<1>> "* BYE
>> kern.srcf.societies.cam.ac.uk IMAP4rev1 server terminating
>> connection^M\n6 OK LOGOUT completed^M\n*** Received corrupted
>> data(-9) - server has terminated the connection abnormally\n")
>> delete-process(#<process imap<2>>)
>
> It seems that Gnus isn't expecting the server to close the
> connection, err, unexpectedly.
>
> Or am I misinterpreting this?

I wouldn't know.

This is a cut-and-past of the relevant portions of *imap-log*.  I
haven't changed anything, other than to replace my password with
something else.

Connecting to '131.111.179.82:993'...
Resolving 'imap.srcf.ucam.org'...
- Certificate type: X.509
 - Certificate info:
 # Certificate is valid since: Wed Aug 14 14:17:00 BST 2002
 # Certificate expires: Thu Aug 14 14:17:00 BST 2003
 # Certificate fingerprint: 0e 51 8a 6b c3 e0 c3 bf d1 54 1e 1b af ab ac cf 
 # Certificate serial number: 00 
 # Certificate version: #3
 # Certificate public key algorithm: RSA
 #   Modulus: 1024 bits
 # CN=imap.srcf.ucam.org,E=sysadmins@srcf.ucam.org,OU=Student-Run Computing Facility,O=University of Cambridge,L=Cambridge,ST=Cambridgeshire,C=UK
 # Certificate Issuer's info:
 # CN=imap.srcf.ucam.org,E=sysadmins@srcf.ucam.org,OU=Student-Run Computing Facility,O=University of Cambridge,L=Cambridge,ST=Cambridgeshire,C=UK

- Peer's certificate is NOT trusted
- Version: TLS 1.0
- Key Exchange: RSA
- Cipher: ARCFOUR 128
- MAC: SHA
- Compression: NULL
- Handshake was completed

- Simple Client Mode:

* OK [CAPABILITY IMAP4REV1 X-NETSCAPE LOGIN-REFERRALS STARTTLS AUTH=LOGIN] localhost IMAP4rev1 2001.315 at Sat, 5 Jul 2003 09:22:10 +0100 (BST)
1 CAPABILITY
* CAPABILITY IMAP4REV1 X-NETSCAPE NAMESPACE MAILBOX-REFERRALS SCAN SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT MULTIAPPEND LOGIN-REFERRALS STARTTLS AUTH=LOGIN
1 OK CAPABILITY completed
2 LOGIN "gs234" "I'm not telling you..."
2 OK [CAPABILITY IMAP4REV1 X-NETSCAPE NAMESPACE MAILBOX-REFERRALS SCAN SORT THREAD=REFERENCES THREAD=ORDEREDSUBJECT MULTIAPPEND] User gs234 authenticated
3 SELECT "INBOX"
* 3 EXISTS
* 0 RECENT
* OK [UIDVALIDITY 1056494962] UID validity status
* OK [UIDNEXT 43763] Predicted next UID
* FLAGS (\Answered \Flagged \Deleted \Draft \Seen)
* OK [PERMANENTFLAGS (\* \Answered \Flagged \Deleted \Draft \Seen)] Permanent flags
3 OK [READ-WRITE] SELECT completed
4 UID SEARCH UNSEEN UNDELETED
* SEARCH
4 OK UID SEARCH completed
5 CLOSE
5 OK CLOSE completed
6 LOGOUT

And this is what I get by setting debug-on-error to t:

Debugger entered--Lisp error: (error "Selecting deleted buffer")
  imap-arrival-filter(#<process imap<1>> "* BYE kern.srcf.societies.cam.ac.uk IMAP4rev1 server terminating connection\r\n6 OK LOGOUT completed\r\n*** Received corrupted data(-9) - server has terminated the connection abnormally\n")

By comparision, this is what I get in *imap-log* on one of those
occasions when the error does not occur:

[snip]
5 OK UID FETCH completed
6 UID STORE 43765 +FLAGS (\Deleted)
* 4 FETCH (FLAGS (\Recent \Deleted) UID 43765)
6 OK UID STORE completed
7 CLOSE
7 OK CLOSE completed
8 LOGOUT
* BYE kern.srcf.societies.cam.ac.uk IMAP4rev1 server terminating connection
8 OK LOGOUT completed
*** Received corrupted data(-9) - server has terminated the connection abnormally

Note the similarities here.  It seems that the "*** Received corrupted
data"... etc. is just gnutls complaining about the other end hanging
up--but that is what it is supposed to do, given that we've gone
through the normal IMAP logout sequence.

So, the problem is that imap-arrival-filter and "Selecting deleted
buffer", whatever that means.  I do not at all know how this stuff
works, but I see that imap-arrival-filter does a 

  (with-current-buffer (process-buffer proc)
    ...

So it seems that the process buffer dies unexpectedly.  But my elisp
skills are insufficiently 1337 to handle this.

-- 
Big Gaute                               http://www.srcf.ucam.org/~gs234/
I want EARS!  I want two ROUND BLACK EARS to make me feel warm 'n secure!!

Re: nnimap versus tls

[Kai Großjohann]

Gaute B Strokkenes <gs234@cam.ac.uk> writes:

> And this is what I get by setting debug-on-error to t:
>
> Debugger entered--Lisp error: (error "Selecting deleted buffer")
>   imap-arrival-filter(#<process imap<1>> "* BYE kern.srcf.societies.cam.ac.uk IMAP4rev1 server terminating connection\n6 OK LOGOUT completed\n*** Received corrupted data(-9) - server has terminated the connection abnormally\n")

Okay, imap.el was sending the LOGOUT command, so that explains why
the connection was taken down.  And I think you correctly diagnosed
the "abnormally" part.

There are only two places in imap.el where a buffer is killed.  This
happens when imap.el tries more than one stream to open a connection
to the remote end.  I wonder if that is the problem?  Can you follow
things on opening the connection to see if this is the cause?
-- 
~/.signature

Re: nnimap versus tls

[Gaute B Strokkenes]

On 5 jul 2003, kai.grossjohann@gmx.net wrote:
> There are only two places in imap.el where a buffer is killed.  This
> happens when imap.el tries more than one stream to open a connection
> to the remote end.  I wonder if that is the problem?  Can you follow
> things on opening the connection to see if this is the cause?

I tried the following:

Index: lisp/imap.el
===================================================================
RCS file: /usr/local/cvsroot/gnus/lisp/imap.el,v
retrieving revision 6.52
diff -u -r6.52 imap.el
--- lisp/imap.el	20 Apr 2003 13:44:27 -0000	6.52
+++ lisp/imap.el	6 Jul 2003 12:34:36 -0000
@@ -995,12 +995,14 @@
 		    (if (null (let ((imap-stream stream))
 				(imap-open-1 (current-buffer))))
 			(progn
+			  (message "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)
+		      (message "kb2: killing buffer `%s'" buffer)
 		      (kill-buffer buffer)
 		      (rename-buffer buffer)
 		      (message "imap: Reconnecting with stream `%s'...done"
@@ -1739,6 +1741,7 @@
       tag)))
 
 (defun imap-wait-for-tag (tag &optional buffer)
+  (message "imap: waiting for tag `%s'" tag)
   (with-current-buffer (or buffer (current-buffer))
     (let (imap-have-messaged)
       (while (and (null imap-continuation)
@@ -1758,9 +1761,11 @@
 	(message ""))
       (and (memq (process-status imap-process) '(open run))
 	   (or (assq tag imap-failed-tags)
-	       (if imap-continuation
-		   'INCOMPLETE
-		 'OK))))))
+	       (progn
+		 (message "imap: done waiting for tag `%s'" tag)
+		 (if imap-continuation
+		     'INCOMPLETE
+		   'OK)))))))
 
 (defun imap-sentinel (process string)
   (delete-process process))
@@ -1780,6 +1785,9 @@
 
 (defun imap-arrival-filter (proc string)
   "IMAP process filter."
+  (message "IAF: trying to grab buffer `%s', proc `%s'"
+	   (process-buffer proc)
+	   proc)
   (with-current-buffer (process-buffer proc)
     (goto-char (point-max))
     (insert string)


I set message-log-max to an insanely large number and waited for the
bug to trigger.  However, no such message appears in the *Message*
buffer.

  Reading active file via nnml...
  nnml: Reading incoming mail from imap...
  imap: Connecting to imap.srcf.ucam.org...
  Opening TLS connection to `imap.srcf.ucam.org'...
  Opening TLS connection with `gnutls-cli -p %p %h'...done
  Opening TLS connection to `imap.srcf.ucam.org'...done
  Waiting for response from imap.srcf.ucam.org...done
  imap: waiting for tag `1'
  imap: done waiting for tag `1'
  imap: Authenticating to `imap.srcf.ucam.org' using `login'...
  imap: Plaintext authentication...
  imap: waiting for tag `2'
  imap: done waiting for tag `2'
  imap: Authenticating to `imap.srcf.ucam.org' using `login'...done
  imap: waiting for tag `3'
  imap: done waiting for tag `3'
  imap: waiting for tag `4'
  imap: done waiting for tag `4'
  imap: waiting for tag `5'
  imap: done waiting for tag `5'
  imap: waiting for tag `6'

Notice how we never get "done waiting for tag `6'"

  nnml: Reading incoming mail from file...
  nnml: Reading incoming mail (no new mail)...done
  Reading active file via nnml...done
  Reading active file from news.gmane.org via nntp...
  Opening nntp server on news.gmane.org...done
  Reading active file from archive via nnfolder...done
  Checking new news...done
  (No changes need to be saved)
  IAF: trying to grab buffer `#<killed buffer>', proc `imap<1>'
  Loading debug...done
  Entering debugger...
   [2 times]
  Mark set [3 times]

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.

Now, looking at the above it seems that the filter does not get to
process anything until after all the other processing that happens
when I hit `g' in the group buffer is done.

I can imagine one slight complication here--I have more than one imap
process running.  That is, I keep most of my mail on a secondary
nnimap server, in addition to which I use an imap mail-source (well,
actually I use fetchmail ATM but I would like to use gnus) to get mail
from another account (which I use for mailing lists and such).  I have
explicitly set the imap mail-source to use :stream tls, but I have not
done this for the nnimap server.  Moreover, when I comment out the
imap mail-source and set the nnimap server to :stream tls I find it
difficult to reproduce this bug.  Thus, one possible twist on my
hypothesis could be that imap.el, when handling my nnimap server,
accidentally deletes a buffer that pertains to my imap mail-source.

I don't know how the emacs process stuff works, and I don't really
understand how imap.el works either.  Unfortunately.

One other thing I should mention is that I do not seem to meet with
succes when I try to use (message "foo") to print debugging messages
in imap-arrival-filter; I'm _sure_ I see message flicker onto my
screen, but I cannot find them in the *Message* buffer afterwards.
Possibly this is just more magick that I am not familiar with.

-- 
Gaute Strokkenes                        http://www.srcf.ucam.org/~gs234/
I can't decide which WRONG TURN to make first!!
 I wonder if BOB GUCCIONE has these problems!

Re: nnimap versus tls

[Kai Großjohann]

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?
-- 
~/.signature

Re: nnimap versus tls

[Gaute B Strokkenes]

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!!

Re: nnimap versus tls

[Kai Großjohann]

Gaute B Strokkenes <gs234@cam.ac.uk> writes:

> 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.

Okay, then another accept-process-output after the loop ought to take
care of it.  Right?

Gnah.  I feel so silly with this stupid kind of advice :-/
I wished I grokked this.
-- 
~/.signature

Re: nnimap versus tls

[Gaute B Strokkenes]

On 7 jul 2003, kai.grossjohann@gmx.net wrote:
> Gaute B Strokkenes <gs234@cam.ac.uk> writes:
>
>> 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.
>
> Okay, then another accept-process-output after the loop ought to
> take care of it.  Right?
>
> Gnah.  I feel so silly with this stupid kind of advice :-/
> I wished I grokked this.

As do I.  However, your advice seems to work.  With the following
imap-wait-for-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)
	    (setq imap-have-messaged t)
	    (message "imap read: %dk" len))
	  (accept-process-output imap-process
				 (truncate imap-read-timeout)
				 (truncate (* (- imap-read-timeout
						 (truncate imap-read-timeout))
					      1000)))))
      (when (and (null imap-continuation)
		 (< imap-reached-tag tag))
	(gs234-debug "imap: accepting a bit extra...")
	(accept-process-output imap-process
			       (truncate imap-read-timeout)
			       (truncate (* (- imap-read-timeout
					       (truncate imap-read-timeout))
					    1000)))
	(gs234-debug "imap: ...done accepting a bit extra"))
      (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)
	       (progn
		 (if imap-continuation
		     'INCOMPLETE
		   'OK)))))))

I get:

  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: going through body of loop
  imap: accepting a bit extra...
  IAF: trying to grab buffer ` *imap source*', proc `imap<1>'

  * BYE kern.srcf.societies.cam.ac.uk IMAP4rev1 server terminating connection
  6 OK LOGOUT completed
  *** Received corrupted data(-9) - server has terminated the connection abnormally
  IAF: imap-state is `auth'
  IAF: punting on imap-parse-response...
  IAF: imap-state is `auth'
  IAF: punting on imap-parse-response...
  imap: ...done accepting a bit extra
  imap: END wait for tag `6'
  imap: imap-reached-tag is now: `6'
  imap: imap-continuation is now: `nil'
  imap: (process-status imap-process) is now: `exit'
  imap: ...closing now done

So we seem to have guessed correctly at last.  ^_^

I'll prepare a (nicer-looking) patch...

-- 
Big Gaute                               http://www.srcf.ucam.org/~gs234/
Is something VIOLENT going to happen to a GARBAGE CAN?

Re: nnimap versus tls

[Gaute B Strokkenes]

On 7 jul 2003, gs234@cam.ac.uk wrote:
> On 7 jul 2003, kai.grossjohann@gmx.net wrote:
>> Gaute B Strokkenes <gs234@cam.ac.uk> writes:
>>
>>> 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.
>>
>> Okay, then another accept-process-output after the loop ought to
>> take care of it.  Right?
>>
>> Gnah.  I feel so silly with this stupid kind of advice :-/
>> I wished I grokked this.

[snip]

> So we seem to have guessed correctly at last.  ^_^
>
> I'll prepare a (nicer-looking) patch...

Well, I now have _two_ patches.  The first one is the stripped down
version of what you've already seen:

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	7 Jul 2003 09:16:34 -0000
@@ -1754,6 +1754,13 @@
 				 (truncate (* (- imap-read-timeout
 						 (truncate imap-read-timeout))
 					      1000)))))
+      (when (and (null imap-continuation)
+		 (< imap-reached-tag tag))
+	(accept-process-output imap-process
+			       (truncate imap-read-timeout)
+			       (truncate (* (- imap-read-timeout
+					       (truncate imap-read-timeout))
+					    1000))))
       (when imap-have-messaged
 	(message ""))
       (and (memq (process-status imap-process) '(open run))

Basically, if we quit the loop due to (process-status imap-process) no
longer being open or run, then we do the accept-process-output thingie
again.  This isn't very pretty, but it's the minimally-intrusive,
maximally safe fix.

The other version:

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	7 Jul 2003 09:18:30 -0000
@@ -1740,15 +1740,19 @@
 
 (defun imap-wait-for-tag (tag &optional buffer)
   (with-current-buffer (or buffer (current-buffer))
-    (let (imap-have-messaged)
+    (let (imap-have-messaged
+	  (imap-more-coming t))
       (while (and (null imap-continuation)
-		  (memq (process-status imap-process) '(open run))
+		  imap-more-coming
+;		  (memq (process-status imap-process) '(open run))
 		  (< imap-reached-tag tag))
 	(let ((len (/ (point-max) 1024))
 	      message-log-max)
 	  (unless (< len 10)
 	    (setq imap-have-messaged t)
 	    (message "imap read: %dk" len))
+	  (setq imap-more-coming
+		(memq (process-status imap-process) '(open run)))
 	  (accept-process-output imap-process
 				 (truncate imap-read-timeout)
 				 (truncate (* (- imap-read-timeout

The idea was to have a flag that tells us when there's no more data
coming out of imap-process.  By only updating the flag just before we
do an accept-process-output, we ensure that we have always read all
that there is to read before we stop.  And this works.  At least, half
the time it does.  The other half Gnus seems to hang while EXAMINE-ing
my nnimap:mail/received folder.  I can't quite figure out what's going
wrong, since setting debug-on-quit to t and/or adding trivial debug
code seems to cause the hang to go away.  I vaguely suspect that this
is some sort of bad timing/scheduling interaction between Emacs and
gnutls-cli, but I have no idea how to test that hypothesis.

In any case, I believe we've found the bug.  I'll leave it to someone
who understands what's going on to actually fix it...

-- 
Gaute Strokkenes                        http://www.srcf.ucam.org/~gs234/
TAPPING?  You POLITICIANS!  Don't you realize that the END of the
 ``Wash Cycle'' is a TREASURED MOMENT for most people?!

Re: nnimap versus tls

[Kai Großjohann]

Gaute B Strokkenes <gs234@cam.ac.uk> writes:

>        (while (and (null imap-continuation)
> -		  (memq (process-status imap-process) '(open run))
> +		  imap-more-coming
> +;		  (memq (process-status imap-process) '(open run))
>  		  (< imap-reached-tag tag))
>  	(let ((len (/ (point-max) 1024))
>  	      message-log-max)
>  	  (unless (< len 10)
>  	    (setq imap-have-messaged t)
>  	    (message "imap read: %dk" len))
> +	  (setq imap-more-coming
> +		(memq (process-status imap-process) '(open run)))
>  	  (accept-process-output imap-process
>  				 (truncate imap-read-timeout)
>  				 (truncate (* (- imap-read-timeout

Here is another idea:

    (setq imap-more-coming
          (or (memq (process-status imap-process) '(open run))
              (accept-process-output ...)))

This means that it will do one more round of the loop if it got some
output last time -- accept-process-output returns non-nil iff some
output was read from the process.

But maybe it is better to just use the first, uglier, version: it
makes it very clear what is happening, and thus people will not be
confused.
-- 
~/.signature

Re: nnimap versus tls

[Gaute B Strokkenes]

On 7 jul 2003, kai.grossjohann@gmx.net wrote:
> Gaute B Strokkenes <gs234@cam.ac.uk> writes:
>
>> (while (and (null imap-continuation)
>> -		  (memq (process-status imap-process) '(open run))
>> +		  imap-more-coming
>> +;		  (memq (process-status imap-process) '(open run))
>> 		  (< imap-reached-tag tag))
>> 	(let ((len (/ (point-max) 1024))
>> 	      message-log-max)
>> 	  (unless (< len 10)
>> 	    (setq imap-have-messaged t)
>> 	    (message "imap read: %dk" len))
>> +	  (setq imap-more-coming
>> +		(memq (process-status imap-process) '(open run)))
>> 	  (accept-process-output imap-process
>> 				 (truncate imap-read-timeout)
>> 				 (truncate (* (- imap-read-timeout
>
> Here is another idea:
>
> (setq imap-more-coming
> (or (memq (process-status imap-process) '(open run))
> (accept-process-output ...)))
>
> This means that it will do one more round of the loop if it got some
> output last time -- accept-process-output returns non-nil iff some
> output was read from the process.

Uhm, I don't quite see why that would help.  Imaging that in one
iteration we receive nothing before we timeout.  Then we received the
server's last gasp, and the status changes to exit.  Then we will miss
the last gasp.  Granted it's a small window of opportunity, but so is
the one that we're already looking at.

> But maybe it is better to just use the first, uglier, version: it
> makes it very clear what is happening, and thus people will not be
> confused.

Well, there was a problem with the prettier version--while it fixed
the problem discussed, but seemed to cause another problem, where the
imap connection would seemingly hang indefinitely.  After much
wailing, gnashing of teeth and debugging (running emacs and gnutls-cli
under strace, modifying source to add debug output etc...) I
determined that the problem seems to lie in gnutls-cli.  I have solved
this for the moment by using openssl instead.  (I might try to debug
gnutls-cli, but I am not in the mood right now.)

However, the fix as it stands is not complete.  Consider the following
(parital) backtrace:

  Debugger entered--Lisp error: (error "Selecting deleted buffer")
    imap-arrival-filter(#<process imap<1>> "*** Received corrupted data(-9) - server has terminated the connection abnormally\n")
    delete-process(#<process imap<2>>)
    imap-close(#<buffer  *imap source*>)

See?  gnutls-cli likes to spit out that line "*** Received
corrupted"... after the connection is closed.  If emacs (and thus
imap-arrival-filter) receives that line separately from the previous
one, then there is a chance that that lone line will still be awaiting
processing after imap-close returns, and so we loose.

Similarly openssl seems to like to write out "read:errno=0" when the
connection goes down.

I still think we should do the extra accept-process-output (it's
obviously the correct thing to do) but this is not enough to protect
us from imap-arrival-filter barfing.  So I suggest that we do what the
emacs lisp manual recommends and wrap the body of imap-arrival-filter
in (when (process-buffer proc) ...).

Index: lisp/imap.el
===================================================================
RCS file: /usr/local/cvsroot/gnus/lisp/imap.el,v
retrieving revision 6.53
diff -u -r6.53 imap.el
--- lisp/imap.el	7 Jul 2003 18:44:13 -0000	6.53
+++ lisp/imap.el	8 Jul 2003 21:55:26 -0000
@@ -1754,15 +1754,13 @@
 				 (truncate (* (- imap-read-timeout
 						 (truncate imap-read-timeout))
 					      1000)))))
-      ;; Maybe the process has died, but the remote end wants to send
-      ;; some more stuff.
+      ;; A process can die _before_ we have processed everything it
+      ;; has to say.  Moreover, this can happen in between the call to
+      ;; accept-process-output and the call to process-status in an
+      ;; iteration of the loop above.
       (when (and (null imap-continuation)
 		 (< imap-reached-tag tag))
-	(accept-process-output imap-process
-			       (truncate imap-read-timeout)
-			       (truncate (* (- imap-read-timeout
-					       (truncate imap-read-timeout))
-					    1000))))
+	(accept-process-output imap-process 0 0))
       (when imap-have-messaged
 	(message ""))
       (and (memq (process-status imap-process) '(open run))
@@ -1789,34 +1787,35 @@
 
 (defun imap-arrival-filter (proc string)
   "IMAP process filter."
-  (with-current-buffer (process-buffer proc)
-    (goto-char (point-max))
-    (insert string)
-    (and imap-log
-	 (with-current-buffer (get-buffer-create imap-log-buffer)
-	   (imap-disable-multibyte)
-	   (buffer-disable-undo)
-	   (goto-char (point-max))
-	   (insert string)))
-    (let (end)
-      (goto-char (point-min))
-      (while (setq end (imap-find-next-line))
-	(save-restriction
-	  (narrow-to-region (point-min) end)
-	  (delete-backward-char (length imap-server-eol))
-	  (goto-char (point-min))
-	  (unwind-protect
-	      (cond ((eq imap-state 'initial)
-		     (imap-parse-greeting))
-		    ((or (eq imap-state 'auth)
-			 (eq imap-state 'nonauth)
-			 (eq imap-state 'selected)
-			 (eq imap-state 'examine))
-		     (imap-parse-response))
-		    (t
-		     (message "Unknown state %s in arrival filter"
-			      imap-state)))
-	    (delete-region (point-min) (point-max))))))))
+  (when (process-buffer proc)
+    (with-current-buffer (process-buffer proc)
+      (goto-char (point-max))
+      (insert string)
+      (and imap-log
+	   (with-current-buffer (get-buffer-create imap-log-buffer)
+	     (imap-disable-multibyte)
+	     (buffer-disable-undo)
+	     (goto-char (point-max))
+	     (insert string)))
+      (let (end)
+	(goto-char (point-min))
+	(while (setq end (imap-find-next-line))
+	  (save-restriction
+	    (narrow-to-region (point-min) end)
+	    (delete-backward-char (length imap-server-eol))
+	    (goto-char (point-min))
+	    (unwind-protect
+		(cond ((eq imap-state 'initial)
+		       (imap-parse-greeting))
+		      ((or (eq imap-state 'auth)
+			   (eq imap-state 'nonauth)
+			   (eq imap-state 'selected)
+			   (eq imap-state 'examine))
+		       (imap-parse-response))
+		      (t
+		       (message "Unknown state %s in arrival filter"
+				imap-state)))
+	      (delete-region (point-min) (point-max)))))))))
 
 \f
 ;; Imap parser.

However, I still feel uneasy about this.  Switching to openssl seems
to trip up the various corner cases I've been talking about a lot
less; I suppose it might be more mature implementation and so causes
much less surprises (gnutls-cli seems to like to write out individual
lines at a time, for instance).  A consequence of my switch is that I
can't really test out this stuff.

I think we really need to run this by someone who understands how this
process stuff and imap.el works (is the original author still around?)
and gain their approval.  I think it's clear that you and I do not
understand precisely how this is supposed to work.

For instance, why does imap-arrival-filter run within delete-process?
The elisp manual states that process output is only accepted when when
emacs is polling for input, or when we explicitly ask for it.  Here is
describe-function has to say about delete-process:

  delete-process is a built-in function.
  (delete-process PROCESS)

  Delete PROCESS: kill it and forget about it immediately.
  PROCESS may be a process, a buffer, the name of a process or buffer, or
  nil, indicating the current buffer's process.

I find this very unintuitive.

Also, why do we get an error at all?  The elisp manual says:

     If an error happens during execution of a filter function, it is
  caught automatically, so that it doesn't stop the execution of
  whatever program was running when the filter function was started.
  However, if `debug-on-error' is non-`nil', the error-catching is
  turned off.  This makes it possible to use the Lisp debugger to
  debug the filter function.  *Note Debugger::.

So why does this error halt gnus?  Granted I've been running with
debug-on-error set to t most of the time while debugging this, but
then why did I see this problem in the first place?  (Maybe gnus does
something special to catch errors when getting mail, (I'm thinking
about that "do you want to continue" message that one gets), I do not
know).

-- 
Gaute Strokkenes                        http://www.srcf.ucam.org/~gs234/
Oh my GOD -- the SUN just fell into YANKEE STADIUM!!

Re: nnimap versus tls

[Kai Großjohann]

Gaute B Strokkenes <gs234@cam.ac.uk> writes:

> However, the fix as it stands is not complete.  Consider the following
> (parital) backtrace:
>
>   Debugger entered--Lisp error: (error "Selecting deleted buffer")
>     imap-arrival-filter(#<process imap<1>> "*** Received corrupted data(-9) - server has terminated the connection abnormally\n")
>     delete-process(#<process imap<2>>)
>     imap-close(#<buffer  *imap source*>)
>
> See?  gnutls-cli likes to spit out that line "*** Received
> corrupted"... after the connection is closed.  If emacs (and thus
> imap-arrival-filter) receives that line separately from the previous
> one, then there is a chance that that lone line will still be awaiting
> processing after imap-close returns, and so we loose.

Argh.  What happens with (while (accept-process-output ...))?  That
means we keep reading stuff until it's enough.

Probably you already tried it, though.
-- 
~/.signature

Re: nnimap versus tls

[Gaute B Strokkenes]

On  9 jul 2003, kai.grossjohann@gmx.net wrote:

> Gaute B Strokkenes <gs234@cam.ac.uk> writes:
>
>> However, the fix as it stands is not complete.  Consider the
>> following (parital) backtrace:
>>
>> Debugger entered--Lisp error: (error "Selecting deleted buffer")
>> imap-arrival-filter(#<process imap<1>> "*** Received corrupted data(-9) - server has terminated the connection abnormally\n")
>> delete-process(#<process imap<2>>)
>> imap-close(#<buffer  *imap source*>)
>>
>> See?  gnutls-cli likes to spit out that line "*** Received
>> corrupted"... after the connection is closed.  If emacs (and thus
>> imap-arrival-filter) receives that line separately from the
>> previous one, then there is a chance that that lone line will still
>> be awaiting processing after imap-close returns, and so we loose.
>
> Argh.  What happens with (while (accept-process-output ...))?  That
> means we keep reading stuff until it's enough.

The thing is, the a subprocess is allowed to give us its output in
however small or large pieces that it feels like, timed in whatever
fashion it fells like.  gnutls-cli seems to like to feed us things
line-by-line; thus the scenario is eminently possible:


gnutls-cli feeds us "6 OK LOGOUT completed"

we read "6 OK LOGOUT completed" with accept-process-output, which
returns non-nil.

Since it returned non-nil, we call accept-process-output again, which
returns nil.

gnutls-cli feeds us "*** Received corrupted data blah-blah", and then
dies.

We check (process-status imap-process) and find that it is dead, and
so return immediately.

Using such a loop would probably make the problem much less likely to
occur, but it _could_ still happen.  And anyway, since it's easy to do
the right thing in all cases, there is no reason not do.

> Probably you already tried it, though.

-- 
Big Gaute                               http://www.srcf.ucam.org/~gs234/
I left my WALLET in the BATHROOM!!

Re: nnimap versus tls

[Kai Großjohann]

Gaute B Strokkenes <gs234@cam.ac.uk> writes:

> However, I still feel uneasy about this.  Switching to openssl seems
> to trip up the various corner cases I've been talking about a lot
> less; I suppose it might be more mature implementation and so causes
> much less surprises (gnutls-cli seems to like to write out individual
> lines at a time, for instance).  A consequence of my switch is that I
> can't really test out this stuff.

Anyhoo.  I committed this.  Thanks for the good work!

I'm sure somebody will see it, somewhen.
-- 
~/.signature

Re: nnimap versus tls

[Gaute B Strokkenes]

On  9 jul 2003, kai.grossjohann@gmx.net wrote:

> Gaute B Strokkenes <gs234@cam.ac.uk> writes:
>
>> However, I still feel uneasy about this.  Switching to openssl
>> seems to trip up the various corner cases I've been talking about a
>> lot less; I suppose it might be more mature implementation and so
>> causes much less surprises (gnutls-cli seems to like to write out
>> individual lines at a time, for instance).  A consequence of my
>> switch is that I can't really test out this stuff.
>
> Anyhoo.  I committed this.  Thanks for the good work!
>
> I'm sure somebody will see it, somewhen.

I feel stupid now.  I just got the following backtrace:

Debugger entered--Lisp error: (error "Selecting deleted buffer")
  imap-arrival-filter(#<process imap> "read:errno=0\n")

(process-buffer proc) evaluates to #<killed buffer>.  Which is to
say, non-nil.

Viz. the emacs manual:

   A filter function that writes the output into the buffer of the
process should check whether the buffer is still alive.  If it tries
to insert into a dead buffer, it will get an error.  The expression
`(buffer-name (process-buffer PROCESS))' returns `nil' if the buffer
is dead.

So we need to change the `when' to `buffer-name'.

-- 
Big Gaute                               http://www.srcf.ucam.org/~gs234/
I have seen these EGG EXTENDERS in my Supermarket..
 ..  I have read the INSTRUCTIONS...

Re: nnimap versus tls

[Kai Großjohann]

Gaute B Strokkenes <gs234@cam.ac.uk> writes:

> So we need to change the `when' to `buffer-name'.

That won't work, but saying (when (buffer-name
(process-buffer...))...) ought to do the trick.  Right?
-- 
~/.signature

Re: nnimap versus tls

[Gaute B Strokkenes]

On 10 jul 2003, kai.grossjohann@gmx.net wrote:

> Gaute B Strokkenes <gs234@cam.ac.uk> writes:
>
>> So we need to change the `when' to `buffer-name'.
>
> That won't work, but saying (when (buffer-name
> (process-buffer...))...) ought to do the trick.  Right?

Argh.  Yes, off course you're right.

-- 
Big Gaute                               http://www.srcf.ucam.org/~gs234/
We are now enjoying total mutual interaction in an imaginary hot tub...

Re: nnimap versus tls

[Simon Josefsson]

Gaute B Strokkenes <gs234@cam.ac.uk> writes:

>   Debugger entered--Lisp error: (error "Selecting deleted buffer")
>     imap-arrival-filter(#<process imap<1>> "*** Received corrupted data(-9) - server has terminated the connection abnormally\n")
>     delete-process(#<process imap<2>>)
>     imap-close(#<buffer  *imap source*>)
>
> See?  gnutls-cli likes to spit out that line "*** Received
> corrupted"... after the connection is closed.

IMHO, gnutls-cli should print this to stderr instead of stdout.

> Similarly openssl seems to like to write out "read:errno=0" when the
> connection goes down.

To stdout?  When -quiet is used?  Then I'd consider this a bug too, it
should go to stderr.

Of course, nnimap should not misbehave even when the tunnel
application print junk to stderr, so your work and patches are still
useful to have.  Thanks.

Re: nnimap versus tls

[Gaute B Strokkenes]

On 10 jul 2003, jas@extundo.com wrote:

> Gaute B Strokkenes <gs234@cam.ac.uk> writes:
>
>> Debugger entered--Lisp error: (error "Selecting deleted buffer")
>> imap-arrival-filter(#<process imap<1>> "*** Received corrupted
>> data(-9) - server has terminated the connection abnormally\n")
>> delete-process(#<process imap<2>>) imap-close(#<buffer *imap
>> source*>)
>>
>> See?  gnutls-cli likes to spit out that line "*** Received
>> corrupted"... after the connection is closed.
>
> IMHO, gnutls-cli should print this to stderr instead of stdout.

It does.  It doesn't make a difference: the elisp manual states that
stderr and stdout of subprocesses can't be separated without using
shell redirection or something similar, and unless I misread the code,
we do no such thing.

>> Similarly openssl seems to like to write out "read:errno=0" when
>> the connection goes down.
>
> To stdout?  When -quiet is used?  Then I'd consider this a bug too,
> it should go to stderr.

It does go to stderr, but as above it makes no difference.

> Of course, nnimap should not misbehave even when the tunnel
> application print junk to stderr,

I'd like to point out that this is not the only problem case that
these patches correct.  There was a race in imap-wait-for-tag, in
which if the process dies we would not necessarily process everything
it output.  This lead to a similar error, but with the tail end of the
imapd's BYE response prepended to "*** Receved...".  I fixed that by
adding a final call to accept-process output, called only when
imap-wait-for-tag ends its loop due to the process exiting.  However,
that didn't the problem of the server outputting extra
junk--imap-wait-for-tag can return as soon as it gets all of the
response to the LOGOUT command, leaving the junk unprocessed (if the
timing is right.)

Looking at imap.el, there are lots of places where 'run and 'close
seem to be used synonymously as process statuses.  I don't think
that's quite correct--a network connection will remain open until
you've read everything the other end has sent you, but a subprocess
will not necessarily stay alive until you've read everything it has to
say.  (Or at least, that's the best estimation of the semantics that I
can make based on my observations; the emacs lisp manual is annoyingly
vague on this particular topic.)

> so your work and patches are still useful to have.  Thanks.

-- 
Gaute Strokkenes                        http://www.srcf.ucam.org/~gs234/
You mean you don't want to watch WRESTLING from ATLANTA?

Re: nnimap versus tls

[Simon Josefsson]

Gaute B Strokkenes <gs234@cam.ac.uk> writes:

>> IMHO, gnutls-cli should print this to stderr instead of stdout.
>
> It does.  It doesn't make a difference: the elisp manual states that
> stderr and stdout of subprocesses can't be separated without using
> shell redirection or something similar, and unless I misread the code,
> we do no such thing.

Should we add a '2>/dev/null' to the imap-*-program variables then?
On the other hand, we need the initial stuff (like 'Client
authentication finished') to notice authentication status, and that is
probably printed to stderr.  Ouch.

Re: nnimap versus tls

[Matthias Andree]

Simon Josefsson <jas@extundo.com> writes:

> Gaute B Strokkenes <gs234@cam.ac.uk> writes:
>
>>> IMHO, gnutls-cli should print this to stderr instead of stdout.
>>
>> It does.  It doesn't make a difference: the elisp manual states that
>> stderr and stdout of subprocesses can't be separated without using
>> shell redirection or something similar, and unless I misread the code,
>> we do no such thing.
>
> Should we add a '2>/dev/null' to the imap-*-program variables then?

Nope. /dev/null doesn't show up in debug or IMAP buffers, and the stderr
output of these openssl or gnutls-cli or whatever stream encoders might
give indispensable help what the user did wrong.

> On the other hand, we need the initial stuff (like 'Client
> authentication finished') to notice authentication status, and that is
> probably printed to stderr.  Ouch.

See :-)

-- 
Matthias Andree

Re: nnimap versus tls

[Kai Großjohann]

Gaute B Strokkenes <gs234@cam.ac.uk> writes:

> Well, I now have _two_ patches.  The first one is the stripped down
> version of what you've already seen:

Does it also work to set the timeout to 0 for the new
accept-process-output?  If it works, that would be nice.
-- 
~/.signature

Re: nnimap versus tls

[Gaute B Strokkenes]

On 7 jul 2003, kai.grossjohann@gmx.net wrote:
> Gaute B Strokkenes <gs234@cam.ac.uk> writes:
>
>> Well, I now have _two_ patches.  The first one is the stripped down
>> version of what you've already seen:
>
> Does it also work to set the timeout to 0 for the new
> accept-process-output?  If it works, that would be nice.

Seems to work.  I'm testing it now.

-- 
Big Gaute                               http://www.srcf.ucam.org/~gs234/
Hey, wait a minute!!  I want a divorce!!..  you're not Clint Eastwood!!