I am running VM 8.1, the Emacs mail reader, connecting via imap to gmail. It can be made to work with stunnel 4.33 providing the encryption, but any version after that causes VM to choke when fetching messages, generating the following error message:
vm-imap-protocol-error: IMAP protocol error: "unexpected char (10)"
Not being an expert in any of the programs that are chained together to make my e-mail setup work, I was able to trace this no deeper than the point where VM reads the buffer Emacs uses for interprocess communication. Sure enough, there is a linefeed in a place where it isn't expected, but it also happens to be the first character in the sequence:
" Process IMAP over SSL finished "
which may be there because of problems deeper than the representation of "newline." At the end of this message I give my attempt to represent the complete contents of the buffer with name "trace of IMAP over SSL session to imap.gmail.com." The ^M's were inserted by hand because cutting and pasting didn't seem to reproduce them.
I realize that I am providing quite a bit of information from VM, and none from stunnel, which is frustrating in an stunnel forum, but I am a complete newbie regarding stunnel. I would be glad to run further experiments with guidance on how to get stunnel itself to generate more useful information. The only reason I suspect it is that installing version 4.33 fixes the problem; but I realize it may be that VM or some other component is violating the rules somehow.
When I say "any version after" 4.33, I mean that I have tried 4.35, the version installed by MacPorts; and 4.49, the latest stable version, recompiled by hand. They behave identically.
-- Drew McDermott Professor of Computer Science Yale Computer Science Department
The interprocess-communication buffer (everything between the dashes, including the newline after "finished," but not including the newline before "starting"):
--------------- starting IMAP over SSL session Tue Nov 29 14:20:01 2011 connecting to imap.gmail.com:993 connected * OK Gimap ready for requests from 128.36.148.241 s17if7011003qao.19 VM CAPABILITY
Process IMAP over SSL finished ---------------
On Tue, 29 Nov 2011 14:35:35 -0500, Drew McDermott wrote:
I am running VM 8.1, the Emacs mail reader, connecting via imap to gmail. It can be made to work with stunnel 4.33 providing the encryption, but any version after that causes VM to choke when fetching messages, generating the following error message:
vm-imap-protocol-error: IMAP protocol error: "unexpected char (10)"
You may wish to investigate this solution: https://bugs.launchpad.net/ubuntu/+source/vm/+bug/321438
Otherwise please send us stunnel logs and stunnel configuration files.
Mike
[Michal Trojnara] On Tue, 29 Nov 2011 14:35:35 -0500, Drew McDermott wrote:
I am running VM 8.1, the Emacs mail reader, connecting via imap to gmail. It can be made to work with stunnel 4.33 providing the encryption, but any version after that causes VM to choke when fetching messages, generating the following error message:
vm-imap-protocol-error: IMAP protocol error: "unexpected char (10)"
You may wish to investigate this solution: https://bugs.launchpad.net/ubuntu/+source/vm/+bug/321438
It doesn't seem to address my problem.
Otherwise please send us stunnel logs and stunnel configuration files.
I have no stunnel configuration file. What should go in it?
Before I could produce the logs, our sysadmin and Unix wizard, Mark Wogahn, kindly did the experiment for me. Here is the relevant part of his note:
... Here is some output from a failed connection, stunnel 4.35, and then a successful connection, stunnel 4.33.
[Failed connection with 4.35 starts here]
11/30/11 2:34:13 PM stunnel[24216] LOG5[24216:140735081020608]: Reading configuration from file /var/folders/G5/G5qCNNmoFgyLcXq2c-9-9+++7nQ/-Tmp-/vm170612634 11/30/11 2:34:13 PM stunnel[24216] LOG5[24216:140735081020608]: Configuration successful 11/30/11 2:34:13 PM stunnel[24216] LOG5[24216:140735081020608]: Clients allowed=125 11/30/11 2:34:13 PM stunnel[24216] LOG5[24216:140735081020608]: stunnel 4.35 on i386-apple-darwin10.8.0 with OpenSSL 1.0.0e 6 Sep 2011 11/30/11 2:34:13 PM stunnel[24216] LOG5[24216:140735081020608]: Threading:PTHREAD SSL:ENGINE Sockets:SELECT,IPv6 Auth:LIBWRAP 11/30/11 2:34:13 PM stunnel[24216] LOG5[24216:140735081020608]: connect_blocking: connected 74.125.45.109:993 11/30/11 2:34:13 PM stunnel[24216] LOG5[24216:140735081020608]: Service stunnel connected remote server from 128.36.229.5:52251 11/30/11 2:34:13 PM stunnel[24216] LOG5[24216:140735081020608]: Error detected on socket (read) file descriptor: Socket operation on non-socket (38) 11/30/11 2:34:13 PM stunnel[24216] LOG5[24216:140735081020608]: Connection reset: 0 bytes sent to SSL, 68 bytes sent to socket 11/30/11 2:34:27 PM login[24217] USER_PROCESS: 24217 ttys003
[Successful connection using 4.33 starts here]
11/30/11 2:40:23 PM stunnel[24298] LOG5[24298:140735081020608]: Reading configuration from file /var/folders/G5/G5qCNNmoFgyLcXq2c-9-9+++7nQ/-Tmp-/vm188660870 11/30/11 2:40:23 PM stunnel[24298] LOG5[24298:140735081020608]: Configuration successful 11/30/11 2:40:23 PM stunnel[24298] LOG5[24298:140735081020608]: Clients allowed=125 11/30/11 2:40:23 PM stunnel[24298] LOG5[24298:140735081020608]: stunnel 4.33 on i386-apple-darwin10.8.0 with OpenSSL 0.9.8r 8 Feb 2011 11/30/11 2:40:23 PM stunnel[24298] LOG5[24298:140735081020608]: Threading:PTHREAD SSL:ENGINE Sockets:SELECT,IPv6 Auth:LIBWRAP 11/30/11 2:40:23 PM stunnel[24298] LOG5[24298:140735081020608]: connect_blocking: connected 74.125.65.108:993 11/30/11 2:40:23 PM stunnel[24298] LOG5[24298:140735081020608]: Service stunnel connected remote server from 128.36.229.5:52277 11/30/11 2:40:23 PM stunnel[24298] LOG5[24298:140735081020608]: Connection closed: 120 bytes sent to SSL, 1208 bytes sent to socket
<End of Wogahn message>
This and some other experiences have convinced me that the "unexpected char (10)" bug is just the surface manifestation of the real problem, which is for versions of stunnel after 4.33, (a) the process created by VM to talk to the IMAP server is dying during the preliminary set up phase for unknown reasons; and (b) when it dies, it produces output that doesn't respect the Windows-newline convention VM expects. The "unexpected char" message masks the more serious generation of a vm-imap-protocol-error with message "IMAP process xxx's buffer has been killed," which would have been signalled if the characters hadn't gotten in the way (I think).
I don't know how robust this bug is across different versions of VM, and I don't know why a change in stunnel suddenly brought it out. Even in version 4.33, the following kind of situation throws VM for a loop: If I put the laptop to sleep by shutting its lid, when I later come back to it if it doesn't wake up and reestablish communnication with the mail server fast enough, the process dies as far as VM is concerned, but what VM sees is the unexpected-character bug. This is especially annoying when traveling, and using those complimentary wifi systems that require you to pledge not to do evil every time you connect to them. You have to remember, every time the computer wakes from a sleep longer than a few minutes, to create a new browser window and click that you Agree to their terms and conditions. If you fail to do this, any software system the tries to connect to the internet will spin its wheels endlessly. Or get a timeout exception, which in the case of VM becomes (you guessed it) an unexpected-character-10 error. VM will work, but you have to be careful not to touch Emacs until you have visited the browser and genuflected before the wifi lawyers.
I've tried some simple repairs of this bug, such as ignoring 10s or treating them newlines, but that doesn't seem to work. VM is expecting a breakdown of the process it's talking to occur in a very particular way, which seems awfully fussy of it.
-- Drew McDermott Professor of Computer Science Yale Computer Science Department
Hi Guys,
This and some other experiences have convinced me that the "unexpected char (10)" bug is just the surface manifestation of the real problem,
I think the real problem was that stunnel executed in inetd mode was sending its last line of logs to stderr, instead of the configured log output (e.g. syslog).
I have fixed this bug here: ftp://ftp.stunnel.org/stunnel/beta/stunnel-4.52b1.tar.gz
Could you please let us know if this version fixes your problem?
Mike
-
Drew McDermott -
Michal Trojnara