5.0.0 OpenSSL compatibility issue: blocking SSL_peek() returns SSL_ERROR_WANT_READ.

[mandree]

I found a difference between OpenSSL proper (1.0.2, 1.1.1, 3.0) and wolfSSL 5.0.0.
My code uses a default setting (blocking I/O) and connects, and then calls SSL_peek() right away. This works in OpenSSL without a hitch, but wolfSSL returns 0 and SSL_get_error() returns SSL_ERROR_WANT_READ.

This incompatibility makes wolfSSL unsuitable as OpenSSL drop-in replacement because it's not bug compatible.

OpenSSL 1.1.1 documents "If SSL_MODE_AUTO_RETRY has been switched off and a non-application data record has been processed, the read function can return and set the error to SSL_ERROR_WANT_READ." - but I am not disabling SSL_MODE_AUTO_RETRY.

[julek-wolfssl]

Hi @mandree, please run your tests against this branch: #4599 with WOLFSSL_FORCE_AUTO_RETRY defined at compile time. Either by adding it to CFLAGS with -DWOLFSSL_FORCE_AUTO_RETRY or by defining it in your user_settings.h header.

[mandree]

Thanks, will try later. FWIW, my application still tolerates OpenSSL 1.0.2 on the assumption that some distributors would backport fixes (possibly under paid support contract) - and formally, this SSL_MODE_AUTO_RETRY was not set in earlier OpenSSL versions either, but for some reason, this issue never cropped up with OpenSSL 1.0.2 either in my testing. I did not dig deeper because OpenSSL 1.1.1 clearly documents this default mode and 1.0.2 is end-of-life.

[mandree]

I can't test since the branch you refer to identifies as 4.1.0 and has an insufficient API, missing, for instance, sk_GENERAL_NAME_free(). I'll be happy to re-test if you point me at some 5.0.0 or newer branch.

[julek-wolfssl]

Hi @mandree, please check that you are correctly checking out the branch. It includes the 5.0 release as well as the API you mentioned. Please try again and let me know if you managed to make progress.

[julek-wolfssl]

@mandree I would just like to ask, is this issue in relation to a specific project you are working on?

[mandree]

Hi @mandree, please check that you are correctly checking out the branch. It includes the 5.0 release as well as the API you mentioned. Please try again and let me know if you managed to make progress.

@julek-wolfssl I just did git clone https://github.com/julek-wolfssl/wolfssl.git which led me to

commit ec4841e (HEAD -> master, origin/master, origin/HEAD)
Merge: 91a41e5 625bd12
Author: Juliusz Sosinowicz <...>
Date: Tue Oct 8 10:20:35 2019 +0200

Merge remote-tracking branch 'wolfSSL/master'

I've now looked specifically for the AUTO_RETRY and got the issue-4593 branch... wasn't clear to me.
So I've built this branch, can confirm that its src/internal.c:8944 has #ifdef WOLFSSL_FORCE_AUTO_RETRY, no dice.
Meaning, still fails. Tries SSL_peek(), gets 0, polls the error, gets WOLFSSL_ERROR_WANT_READ => fetchmail logs socket error and aborts.

mkdir /tmp/wolfssl
cd /tmp/wolfssl
git clone https://github.com/julek-wolfssl/wolfssl.git
git checkout issue-4593
cd wolfssl
mkdir b
./autogen.sh
cd b
CFLAGS=-DWOLFSSL_FORCE_AUTO_RETRY  ../configure -C --enable-debug \
    --enable-opensslall --quiet --enable-harden --prefix=/tmp/ws 
make -j
make install

then fetchmail (from GItlab's branch legacy_64, with git revert 8128bead ; git revert abfc13cf in order to reproduce the failing state that I'd reported here).

../fetchmail-64/configure -C --with-wolfssl=/tmp/ws WOLFSSL_TRUST_FILE=/etc/pki/ca-trust/extracted/pem/tls-ca-bundle.pem && make -j16
FETCHMAIL_WOLFSSL_DEBUG=1 ltrace -o trace ./fetchmail -cvpimap unimail.tu-dortmund.de --auth ssh -v

wolfSSL Entering wolfSSL_CIPHER_get_name
fetchmail: SSL/TLS: using protocol TLSv1.3, cipher TLS_AES_128_GCM_SHA256, 0/0 secret/processed bits
wolfSSL Entering wolfSSL_peek()
wolfSSL Entering wolfSSL_read_internal()
wolfSSL Entering ReceiveData()
growing input buffer

wolfSSL Entering DecryptTls13
received record layer msg
got HANDSHAKE
wolfSSL Entering wolfSSL_get_options
wolfSSL Entering DoTls13HandShakeMsg()
wolfSSL Entering DoTls13HandShakeMsgType
processing new session ticket
wolfSSL Entering DoTls13NewSessionTicket
wolfSSL Leaving DoTls13NewSessionTicket, return 0
Shrinking input buffer

wolfSSL Leaving DoTls13HandShakeMsgType(), return 0
Got Handshake Messge in APP data
wolfSSL Leaving wolfSSL_read_internal(), return 0
wolfSSL Entering SSL_get_error
wolfSSL Leaving SSL_get_error, return 2
wolfSSL Entering SSL_shutdown()
wolfSSL Entering SendAlert
growing output buffer

wolfSSL Entering BuildMessage
wolfSSL Entering BuildTls13Message
wolfSSL Entering EncryptTls13
wolfSSL Leaving BuildTls13Message, return 0
Shrinking output buffer

wolfSSL Leaving SendAlert, return 0
wolfSSL Leaving SSL_shutdown(), return 2
wolfSSL Entering SSL_free
CTX ref count not 0 yet, no free
wolfSSL Entering wolfSSL_sk_SSL_CIPHER_free
wolfSSL Entering wolfSSL_sk_free
wolfSSL Entering wolfSSL_EVP_PKEY_free
wolfSSL Entering wolfSSL_RSA_free
wolfSSL Entering wolfSSL_sk_CIPHER_free
wolfSSL Entering wolfSSL_sk_X509_pop_free
wolfSSL Entering wolfSSL_sk_pop_free
Error, BAD_FUNC_ARG
wolfSSL Entering wolfSSL_sk_X509_pop_free
wolfSSL Entering wolfSSL_sk_pop_free
Error, BAD_FUNC_ARG
wolfSSL Entering wolfSSL_sk_X509_NAME_pop_free
wolfSSL Entering wolfSSL_sk_pop_free
Error, BAD_FUNC_ARG
wolfSSL Leaving SSL_free, return 0
wolfSSL Entering SSL_CTX_free
CTX ref count down to 0, doing full free
wolfSSL Entering wolfSSL_EVP_PKEY_free
wolfSSL Entering wolfSSL_CertManagerFree
wolfSSL Entering wolfSSL_sk_X509_NAME_pop_free
wolfSSL Entering wolfSSL_sk_pop_free
Error, BAD_FUNC_ARG
wolfSSL Leaving SSL_CTX_free, return 0
fetchmail: socket error while fetching from ...omitted...@unimail.tu-dortmund.de

corresponding ltrace is a bit more concise

fprintf(0x7fdde6bcb520, "%s: ", "fetchmail")     = 11
vfprintf(0x7fdde6bcb520, "SSL/TLS: using protocol %s, ciph"..., 0x7ffc5b35c148) = 90
fflush(0x7fdde6bcb520)                           = 0
setitimer(0, 0x7ffc5b35c540, 0, 0x7fdde6af8387)  = 0
setitimer(0, 0x7ffc5b35a380, 0, 0x7fdde6ac650b)  = 0
wolfSSL_peek(0xbb5cc0, 0x7ffc5b35a400, 8192, 0x7fdde6ac650b) = 0
wolfSSL_get_error(0xbb5cc0, 0, 0, 0)             = 2
setitimer(0, 0x7ffc5b35a380, 0, 0)               = 0
sigemptyset(<>)                                  = 0
sigaction(SIGCHLD, { 0x40f6f0, <>, 0, nil }, { 0x40f6f0, <>, 0x5, 0x8 }) = 0
sigaction(SIGPWR, { 0x40f6f0, <>, 0, nil }, nil) = 0
sigemptyset(<>)                                  = 0
sigaction(SIGALRM, { 0x40f720, <>, 0, nil }, { 0x40fae0, <>, 0, nil }) = 0
setitimer(0, 0x7ffc5b35c430, 0, 0x7fdde6c03af3)  = 0
wolfSSL_shutdown(0xbb5cc0, 0x7ffc5b35c430, 0, 0x7fdde6ac650b) = 2
wolfSSL_free(0xbb5cc0, 0, 0, 0)                  = 35
wolfSSL_CTX_free(0xbb52e0, 0, 0, 0)              = 39
close(3)                                         = 0
setitimer(0, 0x7ffc5b35c430, 0, 0x7fdde6c029b7)  = 0
sigemptyset(<>)                                  = 0
sigaction(SIGALRM, { 0x40fae0, <>, 0, nil }, { 0x40f720, <>, 0, 0x7fdde6a5faaa }) = 0
memset(0x44b1a0, '\0', 8193)                     = 0x44b1a0
dcgettext(0, 0x431693, 5, 0x44d180)              = 0x431693
dcgettext(0, 0x432348, 5, 0)                     = 0x432348
fprintf(0x7fdde6bcb440, "%s: ", "fetchmail")     = 11
vfprintf(0x7fdde6bcb440, "%s error while fetching from %s@"..., 0x7ffc5b35c388) = 65
fflush(0x7fdde6bcb440)                           = 0

[julek-wolfssl]

@mandree could you run your test against the master wolfSSL branch with OPENSSL_COMPATIBLE_DEFAULTS defined during compilation? WOLFSSL_FORCE_AUTO_RETRY Is not necessary anymore. This behavior has been added to the OPENSSL_COMPATIBLE_DEFAULTS macro. wolfSSL will always retry reading from a socket with this option turned on. It may be possible that this isn't the case when using BIO's for the network IO. If this does not solve your issue, I will investigate deeper into how fetchmail handles the network IO.

[mandree]

@julek-wolfssl tried it with wolfssl as of 4e1c39b. wolfSSL identifies as 5.0.1 and I've confirmed that the option landed in CFLAGS, fetchmail 6.4.25 with the two git revert shown above.

_build/Makefile
2734:CCASFLAGS = -DOPENSSL_COMPATIBLE_DEFAULTS -O2 -ggdb -pipe  
2736:CFLAGS = -DOPENSSL_COMPATIBLE_DEFAULTS -O2 -ggdb -pipe   -g -O0 -Wno-pragmas -Wall -Wno-strict-aliasing -Wextra -Wunknown-pragmas --param=ssp-buffer-size=1 -Waddress -Warray-bounds -Wbad-function-cast -Wchar-subscripts -Wcomment -Wfloat-equal -Wformat-security -Wformat=2 -Wmaybe-uninitialized -Wmissing-field-initializers -Wmissing-noreturn -Wmissing-prototypes -Wnested-externs -Wnormalized=id -Woverride-init -Wpointer-arith -Wpointer-sign -Wredundant-decls -Wshadow -Wsign-compare -Wstrict-overflow=1 -Wswitch-enum -Wundef -Wunused -Wunused-result -Wunused-variable -Wwrite-strings -fwrapv

Still no joy. wolfSSL debug output first, which shows that the read takes place.
I can confirm that with ltrace -S that SSL_peek recvfrom()s 5 bytes, then 250 bytes, and returns 0, that is when fetchmail calls SSL_get_error() and receives 2 (SSL_WANT_READ).

wolfSSL Leaving wolfSSL_connect_TLSv13(), return 1
wolfSSL Entering wolfSSL_get_version
wolfSSL Entering SSL_get_current_cipher
wolfSSL Entering wolfSSL_CIPHER_get_bits
wolfSSL Entering wolfSSL_CIPHER_get_name
fetchmail: SSL/TLS: using protocol TLSv1.3, cipher TLS_AES_128_GCM_SHA256, 128/0 secret/processed bits
wolfSSL Entering wolfSSL_peek()
wolfSSL Entering wolfSSL_read_internal()
wolfSSL Entering ReceiveData()
growing input buffer
wolfSSL Entering DecryptTls13
received record layer msg
got HANDSHAKE
wolfSSL Entering wolfSSL_get_options
wolfSSL Entering DoTls13HandShakeMsg()
wolfSSL Entering DoTls13HandShakeMsgType
processing new session ticket
wolfSSL Entering DoTls13NewSessionTicket
wolfSSL Leaving DoTls13NewSessionTicket, return 0
Shrinking input buffer
wolfSSL Leaving DoTls13HandShakeMsgType(), return 0
Got Handshake Messge in APP data
wolfSSL Leaving wolfSSL_read_internal(), return 0
wolfSSL Entering SSL_get_error
wolfSSL Leaving SSL_get_error, return 2
wolfSSL Entering SSL_shutdown()
wolfSSL Entering SendAlert
[...]
wolfSSL Leaving SSL_CTX_free, return 0
fetchmail: socket error while fetching from WHOEVER@unimail.tu-dortmund.de
fetchmail: 6.4.25 querying unimail.tu-dortmund.de (protocol IMAP) at So 26 Dez 2021 21:29:51 CET: poll completed

relevant ltrace -S ./fetchmail -cv unimail.tu-dortmund.de -pimap --auth ssh -v --ssl:

wolfSSL_peek(0x13b5cc0, 0x7ffd0a41d3a0, 8192, 0x7f59e2c9f50b <unfinished ...>
recvfrom@SYS(3, 0x13b5f20, 5, 0)                 = 5
recvfrom@SYS(3, 0x13fc0d0, 250, 0)               = 250
<... wolfSSL_peek resumed> )                     = 0
wolfSSL_get_error(0x13b5cc0, 0, 0x13b5cc0, 5116) = 2
setitimer(0, 0x7ffd0a41d320, 0, 5116 <unfinished ...>
setitimer@SYS(0, 0x7ffd0a41d320, 0, 0x7f59e2f69e08) = 0
<... setitimer resumed> )                        = 0
sigemptyset(<>)                                  = 0
sigaction(SIGCHLD, { 0x40f6f0, <>, 0, nil } <unfinished ...>
rt_sigaction@SYS(17, 0x7ffd0a41f150, 0x7ffd0a41f1f0, 8) = 0
<... sigaction resumed> , { 0x40f6f0, <>, 0x5, 0x8 }) = 0
sigaction(SIGPWR, { 0x40f6f0, <>, 0, nil } <unfinished ...>
rt_sigaction@SYS(30, 0x7ffd0a41f150, 0, 8)       = 0
<... sigaction resumed> , nil)                   = 0
sigemptyset(<>)                                  = 0
sigaction(SIGALRM, { 0x40f720, <>, 0, nil } <unfinished ...>
rt_sigaction@SYS(14, 0x7ffd0a41f110, 0x7ffd0a41f1b0, 8) = 0
<... sigaction resumed> , { 0x40fae0, <>, 0, nil }) = 0
setitimer(0, 0x7ffd0a41f3d0, 0, 0x7f59e2ddcaf3 <unfinished ...>
setitimer@SYS(0, 0x7ffd0a41f3d0, 0, 8)           = 0
<... setitimer resumed> )                        = 0
wolfSSL_shutdown(0x13b5cc0, 0x7ffd0a41f3d0, 0, 0x7f59e2c9f50b <unfinished ...>
sendto@SYS(3, 0x13bb1d0, 24, 0)                  = 24
<... wolfSSL_shutdown resumed> )                 = 2
wolfSSL_free(0x13b5cc0, 2, 67, 0x13ba64b)        = 0
wolfSSL_CTX_free(0x13b52e0, 0, 0x7f59e2da3a60, 3377) = 0
close(3 <unfinished ...>
close@SYS(3)                                     = 0
<... close resumed> )                            = 0
setitimer(0, 0x7ffd0a41f3d0, 0, 0x7f59e2ddb9b7 <unfinished ...>
setitimer@SYS(0, 0x7ffd0a41f3d0, 0, 0x7f59e2f704f8) = 0
<... setitimer resumed> )                        = 0
sigemptyset(<>)                                  = 0
sigaction(SIGALRM, { 0x40fae0, <>, 0, nil } <unfinished ...>
rt_sigaction@SYS(14, 0x7ffd0a41f150, 0x7ffd0a41f1f0, 8) = 0
<... sigaction resumed> , { 0x40f720, <>, 0xa41f250, 0x90be25784b740f00 }) = 0
memset(0x44b1a0, '\0', 8193)                     = 0x44b1a0
dcgettext(0, 0x431693, 5, 0x44d180)              = 0x431693
dcgettext(0, 0x432348, 5, 0)                     = 0x432348
fprintf(0x7f59e2da4440, "%s: ", "fetchmail" <unfinished ...>
write@SYS(2, "fetchmail: ", 11fetchmail: )                  = 11
<... fprintf resumed> )                          = 11
vfprintf(0x7f59e2da4440, "%s error while fetching from %s@"..., 0x7ffd0a41f328 <unfinished ...>
write@SYS(2, "socket error while fetching from"..., 65socket error while fetching from WHOEVER@unimail.tu-dortmund.de

This is the output with OpenSSL 1.1.1l (Lima) - note it reads more chunks. Is there something special that wolfSSL read 5 then 250 bytes, and OpenSSL read 5 then 266 bytes? Is the difference related to recvfrom() vs read()? Other than that, with a zero flags argument these should behave identically.

SSL_peek(0x5654f1acbe40, 0x7ffc46cf5b10, 8192, 0x7f54fd3b650b <unfinished ...>
read@SYS(3, "\027\003\003\001\n", 5)             = 5
read@SYS(3, "~\335:\335\262x\305\322NZ\022|\b}xf\266\255\032\204o\346\275W"V\310i\037\206\363S"..., 266) = 266
read@SYS(3, "\027\003\003\001\n", 5)             = 5
read@SYS(3, "w\373G\213&\236\316\347qp\376\025#\307\306Gjxx\257\334T\334M\fr\352\001\023,yA"..., 266) = 266
read@SYS(3, "\027\003\003", 5)                   = 5
read@SYS(3, "F\215\222\b|\246\266td=\243F\026\255$V\351\356l\b/f`\001Q\205\276N\335\024\371N"..., 133) = 133
<... SSL_peek resumed> )                         = 116
memchr("* OK [CAPABILITY IMAP4rev1 LITER"..., '\n', 116) = 0x7ffc46cf5b83
SSL_read(0x5654f1acbe40, 0x7ffc46cf5b10, 116, 16) = 116
setitimer(0, 0x7ffc46cf5a70, 0, 0x7ffc46cf5b10 <unfinished ...>
setitimer@SYS(0, 0x7ffc46cf5a70, 0, 1)           = 0
<... setitimer resumed> )                        = 0
strlen("* OK [CAPABILITY IMAP4rev1 LITER"...)    = 116
__fprintf_chk(0x7f54fd4bb520, 1, 0x5654f0e3e718, 0x7ffc46d00347) = 11
__vfprintf_chk(0x7f54fd4bb520, 1, 0x5654f0e43050, 0x7ffc46cf5980) = 121
fflush(0x7f54fd4bb520 <unfinished ...>
write@SYS(1, "fetchmail: IMAP< * OK [CAPABILIT"..., 132fetchmail: IMAP< * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=LOGIN AUTH=PLAIN SASL-IR] unimail Cyrus IMAP 3.4.2 server ready
) = 132
<... fflush resumed> )                           = 0
[...]

[mandree]

@julek-wolfssl I have toyed with my code and have it read and cache 1 byte when SSL_peek() returns SSL_ERROR_WANT_READ, then things seem to work. Not sure what is the difference here inside wolfSSL, with that code in place, I get this ltrace -S:

wolfSSL_peek(0xca7cc0, 0x7ffebcb17e30, 8192, 0x7fc720e9a50b <unfinished ...>
recvfrom@SYS(3, 0xca7f20, 5, 0)                  = 5
recvfrom@SYS(3, 0xcee280, 250, 0)                = 250
<... wolfSSL_peek resumed> )                     = 0
wolfSSL_get_error(0xca7cc0, 0, 0xca7cc0, 3310)   = 2
wolfSSL_read(0xca7cc0, 0x7ffebcb17e30, 1, 3310 <unfinished ...>
recvfrom@SYS(3, 0xca7f20, 5, 0)                  = 5
recvfrom@SYS(3, 0xcee280, 250, 0)                = 250
recvfrom@SYS(3, 0xca7f20, 5, 0)                  = 5
recvfrom@SYS(3, 0xcada80, 133, 0)                = 133
<... wolfSSL_read resumed> )                     = 1
wolfSSL_peek(0xca7cc0, 0x7ffebcb17e31, 8191, 1)  = 115
memchr(" OK [CAPABILITY IMAP4rev1 LITERA"..., '\n', 115) = 0x7ffebcb17ea3
wolfSSL_read(0xca7cc0, 0x7ffebcb17e31, 115, 15)  = 115
setitimer(0, 0x7ffebcb17db0, 0, 3245 <unfinished ...>
setitimer@SYS(0, 0x7ffebcb17db0, 0, 0x7fc720de5d20) = 0
<... setitimer resumed> )                        = 0
strlen("* OK [CAPABILITY IMAP4rev1 LITER"...)    = 116
fprintf(0x7fc720f9f520, "%s: ", "fetchmail")     = 11
vfprintf(0x7fc720f9f520, "%s< %s\n", 0x7ffebcb17cf8) = 121
fflush(0x7fc720f9f520 <unfinished ...>
write@SYS(1, "fetchmail: IMAP< * OK [CAPABILIT"..., 132fetchmail: IMAP< * OK [CAPABILITY IMAP4rev1 LITERAL+ ID ENABLE AUTH=LOGIN AUTH=PLAIN SASL-IR] unimail Cyrus IMAP 3.4.2 server ready
) = 132
<... fflush resumed> )                           = 0

[mandree]

Note that for all output above, fetchmail calls SSL_CTX_set_mode(), but wolfSSL 5.0.0 refuses that code with "Not implemented", the master branch at rev shown above accepts it, but somehow does not heed it. I still need to force this one-byte read.

[mandree]

On another server (imap.gmx.net) that I am trying, I find that the CAPABILITY received from the server is shorter, and that seems to pose no problem, SSL_peek then returns 222. So might this be some buffer sizhe rounding/retry issue?

This is on imap.gmx.net, where SSL_peek() returns 222:

wolfSSL_peek(0xa2c070, 0x7ffed523ea70, 8192, 0x7f67f60c750b <unfinished ...>
recvfrom@SYS(3, 0xa2c2d0, 5, 0)                  = 5
recvfrom@SYS(3, 0xa2a0a0, 239, 0)                = 239
<... wolfSSL_peek resumed> )                     = 222
memchr("* CAPABILITY IMAP4rev1 CHILDREN "..., '\n', 222) = 0x7ffed523eb2e
wolfSSL_read(0xa2c070, 0x7ffed523ea70, 191, 16)  = 191
setitimer(0, 0x7ffed523e9f0, 0, 191 <unfinished ...>
setitimer@SYS(0, 0x7ffed523e9f0, 0, 0x7f67f6397e20) = 0
<... setitimer resumed> )                        = 0
strlen("* CAPABILITY IMAP4rev1 CHILDREN "...)    = 191
fprintf(0x7f67f61cc520, "%s: ", "fetchmail")     = 11
vfprintf(0x7f67f61cc520, "%s< %s\n", 0x7ffed523e938) = 196
fflush(0x7f67f61cc520 <unfinished ...>
write@SYS(1, "fetchmail: IMAP< * CAPABILITY IM"..., 207fetchmail: IMAP< * CAPABILITY IMAP4rev1 CHILDREN ENABLE ID IDLE LIST-EXTENDED LIST-ST
ATUS LITERAL- MOVE NAMESPACE SASL-IR SORT SPECIAL-USE THREAD=ORDEREDSUBJECT UIDPLUS UNSELECT WITHIN AUTH=LOGIN AUTH=PLAIN
) = 207
<... fflush resumed> )                           = 0

[mandree]

Apparently there are handshaking differences. This is the wolfSSL debug output for imap.gmx.net - note that the failing server makes wolfSSL log "received record layer msg -> got app DATA" above, while the working one makes wolfSSL log "received record layer msg -> got app DATA":

wolfSSL Entering wolfSSL_peek()
wolfSSL Entering wolfSSL_read_internal()
wolfSSL Entering ReceiveData()
growing input buffer
wolfSSL Entering DecryptTls13
received record layer msg
got app DATA
wolfSSL Leaving ReceiveData(), return 222
wolfSSL Leaving wolfSSL_read_internal(), return 222
wolfSSL Entering wolfSSL_read()
wolfSSL Entering wolfSSL_read_internal()
wolfSSL Entering ReceiveData()
wolfSSL Leaving ReceiveData(), return 191
wolfSSL Leaving wolfSSL_read_internal(), return 191
fetchmail: IMAP< * CAPABILITY IMAP4rev1 CHILDREN ENABLE ID IDLE LIST-EXTENDED LIST-STATUS LITERAL- MOVE NAMESPACE SASL-IR SORT SPECIAL-USE THREAD=ORDEREDSUBJECT UIDPLUS UNSELECT WITHIN AUTH=LOGIN AUTH=PLAIN
fetchmail: Protocol identified as IMAP4 rev 1

[julek-wolfssl]

Hi @mandree , is it possible for you to provide the full wolfSSL logs of a faulty connection (possibly intertwined with fetchmail logs to show where the error occurs)? I have some ideas on why this might still be an issue for fetchmail but I would need the full logs to confirm. If you do not wish to upload the logs here, you may email them to support@wolfssl.com.

The shorter read from wolfSSL may be from fewer extensions being set in the ClientHello which are then replied to in the ServerHello.

fetchmail calls SSL_CTX_set_mode(), but wolfSSL 5.0.0 refuses that code with "Not implemented"

Could you check what mode is fetchmail trying to set? If it is SSL_MODE_AUTO_RETRY then it appears that you are not using the correct version of wolfSSL. You may try to use the latest master version as the pull request has been merged.

[mandree]

@julek-wolfssl now trying wolfSSL master as of 5910ada, and fetchmail 6.4.26 (branch legacy_6x) with git revert 6a5484e03 8128beadf which is important to remove the wolfSSL compat workarounds. wolfSSL identifies as 5.1.2 (./fetchmail -V after the build).

Note 1: I have figured the error is TLS 1.3 specific and will not happen with TLS 1.2 or 1.1 (add --sslproto tls1.2 to fetchmail invocation below).

Note 2: in wolfSSL's configure, I cannot pass the auto retry flag with env CFLAGS=-DWOLFSSL_FORCE_AUTO_RETRY ../configure ... any more because that somehow loses OpenSSL compatibility flags, which I have not investigated, at any rate the fetchmail build bombs out. I believe this was not the case with 5.0, but consider this unconfirmed for now.

For the log below:
wolfSSL uses ../configure -C --enable-debug --enable-opensslall --enable-harden --prefix=/tmp/ws && make -j && make install
fetchmail uses ./configure -C --with-wolfssl=/tmp/ws WOLFSSL_TRUST_FILE=/etc/pki/ca-trust/extracted/pem/tls-ca-bundle.pem (adjust the trust file as needed)

then running fetchmail locally under ltrace yields:

env FETCHMAILHOME=/tmp/fm FETCHMAIL_WOLFSSL_DEBUG=1 \
ltrace \
./fetchmail -c -vvv -p imap unimail.tu-dortmund.de --auth ssh --user amnesiac
...
getenv("FETCHMAIL_DISABLE_CBC_IV_COUNTER"...)    = nil
wolfSSL_CTX_set_options(0xc2bb80, 0x400013ff, 1023, 0xffefff80wolfSSL Entering SSL_CTX_set_options
        WOLFSSL_OP_NO_SSLv2 : wolfSSL does not support SSLv2
        SSL_OP_NO_SSLv3
) = 0x400013ff
wolfSSL_CTX_set_mode(0xc2bb80, 3, 0x400013ff, 0x7fd930efa7f7wolfSSL Entering SSL_CTX_set_mode
) = 3
wolfSSL_CTX_set_verify(0xc2bb80, 1, 0x408670, 0x7fd930efa7f7wolfSSL Entering wolfSSL_CTX_set_verify
) = 0xc2bb80
getenv("FETCHMAIL_INCLUDE_DEFAULT_X509_C"...)    = nil
wolfSSL_CTX_load_verify_locations(0xc2bb80, 0x42b968, 0, 0xffffff80wolfSSL_CTX_load_verify_locations_ex
Getting dynamic buffer
Processing CA PEM file
wolfSSL Entering PemToDer
Adding a CA
...
fprintf(0x7fd930ff45a0, "%s: ", "fetchmail")     = 11
vfprintf(0x7fd930ff45a0, "SSL/TLS: using protocol %s, ciph"..., 0x7ffcbbf4dea8) = 92
fflush(0x7fd930ff45a0fetchmail: SSL/TLS: using protocol TLSv1.3, cipher TLS_AES_128_GCM_SHA256, 128/0 secret/processed bits
)                           = 0
dcgettext(0, 0x43b4a0, 5, 0x7fd930efa7f7)        = 0x43b4a0
fprintf(0x7fd930ff45a0, "%s: ", "fetchmail")     = 11
vfprintf(0x7fd930ff45a0, "%s: upgrade to TLS succeeded.\n", 0x7ffcbbf4e0e8) = 50
fflush(0x7fd930ff45a0fetchmail: unimail.tu-dortmund.de: upgrade to TLS succeeded.
)                           = 0
memset(0x44b1a0, '\0', 8193)                     = 0x44b1a0
sprintf("A0002", "A%04u", 2)                     = 5
snprintf("A0002 ", 8191, "%s ", "A0002")         = 6
strlen("A0002 ")                                 = 6
vsnprintf("CAPABILITY", 8185, "CAPABILITY", 0x7ffcbbf4c0c8) = 10
strlen("A0002 CAPABILITY")                       = 16
snprintf("\r\n", 8177, "\r\n")                   = 2
strlen("A0002 CAPABILITY\r\n")                   = 18
wolfSSL_write(0xc2c560, 0x7ffcbbf4c0e0, 18, 0wolfSSL Entering SSL_write()
growing output buffer
wolfSSL Entering BuildTls13Message
wolfSSL Entering EncryptTls13
wolfSSL Leaving BuildTls13Message, return 0
Shrinking output buffer
wolfSSL Leaving SSL_write(), return 18
)   = 18
strlen("A0002 CAPABILITY\r\n")                   = 18
fprintf(0x7fd930ff45a0, "%s: ", "fetchmail")     = 11
vfprintf(0x7fd930ff45a0, "%s> %s\n", 0x7ffcbbf4bfd8) = 23
fflush(0x7fd930ff45a0fetchmail: IMAP> A0002 CAPABILITY
)                           = 0
setitimer(0, 0x7ffcbbf49fd0, 0, 0x7fd930efa7f7)  = 0
wolfSSL_peek(0xc2c560, 0x7ffcbbf4a050, 8192, 0x7fd930ec8d3bwolfSSL Entering wolfSSL_peek()
wolfSSL Entering wolfSSL_read_internal()
wolfSSL Entering ReceiveData()
growing input buffer
wolfSSL Entering DecryptTls13
received record layer msg
got HANDSHAKE
wolfSSL Entering wolfSSL_get_options
wolfSSL Entering DoTls13HandShakeMsg()
wolfSSL Entering DoTls13HandShakeMsgType
processing new session ticket
wolfSSL Entering DoTls13NewSessionTicket
wolfSSL Leaving DoTls13NewSessionTicket, return 0
Shrinking input buffer
wolfSSL Leaving DoTls13HandShakeMsgType(), return 0
Got Handshake Messge in APP data
wolfSSL Leaving wolfSSL_read_internal(), return 0
) = 0
wolfSSL_get_error(0xc2c560, 0, 0, 0x7fd930efa7f7wolfSSL Entering SSL_get_error
wolfSSL Leaving SSL_get_error, return 2
) = 2
setitimer(0, 0x7ffcbbf49fd0, 0, 0x7fd930efa7f7)  = 0
setitimer(0, 0x7ffcbbf4e3e0, 0, 0x7fd930ec8d3b)  = 0
dcgettext(0, 0x43150e, 5, 0xc23a50)              = 0x43150e
fprintf(0x7fd930ff44c0, "%s: ", "fetchmail"fetchmail: )     = 11
vfprintf(0x7fd930ff44c0, "Socket or TLS error on %s@%s\n", 0x7ffcbbf4e228Socket or TLS error on amnesiac@unimail.tu-dortmund.de
) = 55
fflush(0x7fd930ff44c0)                           = 0
...
wolfSSL_shutdown(0xc2c560, 0x7ffcbbf4e2d0, 0, 0x7fd930ec8d3bwolfSSL Entering SSL_shutdown()
...

and this is the latter part with ltrace -S -o trace (trace syscalls and keep ltrace log separate) and one less -v and --ssl to go to Implicit TLS mode for fetchmail (FETCHMAILHOME=/tmp/fm FETCHMAIL_WOLFSSL_DEBUG=1 ltrace -S -o trace ./fetchmail -cvpimap unimail.tu-dortmund.de --auth ssh --user amnesiac --ssl):

fprintf(0x7f252e2525a0, "%s: ", "fetchmail")                                     = 11
vfprintf(0x7f252e2525a0, "SSL/TLS: using protocol %s, ciph"..., 0x7ffcb4884688 <unfinished ...>
write@SYS(1, "fetchmail: SSL/TLS: using protoc"..., 103)                         = 103
<... vfprintf resumed> )                                                         = 92
fflush(0x7f252e2525a0)                                                           = 0
setitimer(0, 0x7ffcb4884a80, 0, 3072 <unfinished ...>
setitimer@SYS(0, 0x7ffcb4884a80, 0, 0)                                           = 0
<... setitimer resumed> )                                                        = 0
setitimer(0, 0x7ffcb48828c0, 0, 0x7f252e126d3b <unfinished ...>
setitimer@SYS(0, 0x7ffcb48828c0, 0, 0)                                           = 0
<... setitimer resumed> )                                                        = 0
wolfSSL_peek(0x1a52950, 0x7ffcb4882940, 8192, 0x7f252e126d3b <unfinished ...>
write@SYS(2, "wolfSSL Entering wolfSSL_peek()\n"..., 32)                         = 32
write@SYS(2, "wolfSSL Entering wolfSSL_read_in"..., 41)                          = 41
write@SYS(2, "wolfSSL Entering ReceiveData()\n", 31)                             = 31
recvfrom@SYS(3, 0x1a52bb0, 5, 0)                                                 = 5
write@SYS(2, "growing input buffer\n", 21)                                       = 21
recvfrom@SYS(3, 0x1a87180, 250, 0)                                               = 250
write@SYS(2, "wolfSSL Entering DecryptTls13\n", 30)                              = 30
write@SYS(2, "received record layer msg\n", 26)                                  = 26
write@SYS(2, "got HANDSHAKE\n", 14)                                              = 14
write@SYS(2, "wolfSSL Entering wolfSSL_get_opt"..., 37)                          = 37
write@SYS(2, "wolfSSL Entering DoTls13HandShak"..., 39)                          = 39
write@SYS(2, "wolfSSL Entering DoTls13HandShak"..., 41)                          = 41
write@SYS(2, "processing new session ticket\n", 30)                              = 30
write@SYS(2, "wolfSSL Entering DoTls13NewSessi"..., 41)                          = 41
write@SYS(2, "wolfSSL Leaving DoTls13NewSessio"..., 50)                          = 50
write@SYS(2, "Shrinking input buffer\n", 23)                                     = 23
write@SYS(2, "wolfSSL Leaving DoTls13HandShake"..., 52)                          = 52
write@SYS(2, "Got Handshake Messge in APP data"..., 33)                          = 33
write@SYS(2, "wolfSSL Leaving wolfSSL_read_int"..., 50)                          = 50
<... wolfSSL_peek resumed> )                                                     = 0
wolfSSL_get_error(0x1a52950, 0, 0, 0x7f252e1587f7 <unfinished ...>
write@SYS(2, "wolfSSL Entering SSL_get_error\n", 31)                             = 31
write@SYS(2, "wolfSSL Leaving SSL_get_error, r"..., 40)                          = 40
<... wolfSSL_get_error resumed> )                                                = 2

[This is the place where fetchmail concludes the connection is severed and shuts down the session, 
the socket error is logged after TLS shutdown.]

setitimer(0, 0x7ffcb48828c0, 0, 0x7f252e1587f7 <unfinished ...>
setitimer@SYS(0, 0x7ffcb48828c0, 0, 0x7f252e20d3e0)                              = 0
<... setitimer resumed> )                                                        = 0
wolfSSL_shutdown(0x1a52950, 0x7ffcb4884970, 0, 0x7f252e126d3b <unfinished ...>
write@SYS(2, "wolfSSL Entering SSL_shutdown()\n"..., 32)                         = 32
...
write@SYS(2, "wolfSSL Entering wolfSSL_sk_pop_"..., 37)                          = 37
write@SYS(2, "wolfSSL Leaving SSL_CTX_free, re"..., 39)                          = 39
<... wolfSSL_CTX_free resumed> )                                                 = 39

[Fetchmail closes the TCP socket here:]

close(3 <unfinished ...>
close@SYS(3)                                                                     = 0
<... close resumed> )                                                            = 0
setitimer(0, 0x7ffcb4884970, 0, 0x7f252e158ed7 <unfinished ...>
setitimer@SYS(0, 0x7ffcb4884970, 0, 0x7f252e20d3e0)                              = 0
<... setitimer resumed> )                                                        = 0
sigemptyset(<>)                                                                  = 0
sigaction(SIGALRM, { 0x40fb00, <>, 0, nil } <unfinished ...>
rt_sigaction@SYS(14, 0x7ffcb48846f0, 0x7ffcb4884790, 8)                          = 0
<... sigaction resumed> , { 0x40f740, <>, 0, 0x7f252e0b488a })                   = 0
memset(0x44b1a0, '\0', 8193)                                                     = 0x44b1a0
dcgettext(0, 0x431693, 5, 0x44d121)                                              = 0x431693
dcgettext(0, 0x432348, 5, 0)                                                     = 0x432348
fprintf(0x7f252e2524c0, "%s: ", "fetchmail" <unfinished ...>
write@SYS(2, "fetchmail: ", 11)                                                  = 11
<... fprintf resumed> )                                                          = 11
vfprintf(0x7f252e2524c0, "%s error while fetching from %s@"..., 0x7ffcb48848c8 <unfinished ...>
write@SYS(2, "socket error while fetching from"..., 65)                          = 65
<... vfprintf resumed> )                                                         = 65

[julek-wolfssl]

@mandree I've found an issue with how we're currently implementing the auto retry logic. It should only retry reads and writes for handshake messages. The way that I have solved this in a working branch is with:

diff --git a/src/internal.c b/src/internal.c
index 88c6d74f3..621316d01 100644
--- a/src/internal.c
+++ b/src/internal.c
@@ -8980,7 +8980,7 @@ retry:
                 return -1;
 
             case WOLFSSL_CBIO_ERR_WANT_READ:      /* want read, would block */
-                if (ssl->ctx->autoRetry)
+                if (ssl->ctx->autoRetry && !ssl->options.handShakeDone)
                     goto retry;
                 return WANT_READ;

I recommend applying this patch to your version of wolfSSL so that fetchmail will still receive WANT_{READ|WRITE} when not in a handshake.

[mandree]

@julek-wolfssl this is going in the wrong direction. An application that uses blocking I/O (breaking free with alarm(some_timeout_value); and a SIGALRM handler) and that sets the SSL_MODE_AUTO_RETRY mode should never see a WANT_READ or WANT_WRITE code because it will not implement retry logic.

[julek-wolfssl]

You are correct @mandree. I will need to run fetchmail myself to be able to better comment on what is happening. I will try to get back to you with results as soon as possible!

[julek-wolfssl]

Hi @mandree, I have compiled and tried running the version of fetchmail you specified (e7ee3344792931d8d9439cc0f79dbcc726580187) with wolfSSL but I am receiving the error that I am not logged in. Is it possible for you to provide the full logs to support@wolfssl.com?

My build configuration:

# wolfSSL
./configure --enable-opensslall --enable-harden
make -j
make install
# fetchmail
./configure --with-wolfssl WOLFSSL_TRUST_FILE=webmail-tu-dortmund-de-chain.pem
make -j

# Then I ran
./fetchmail -cvpimap unimail.tu-dortmund.de --auth ssh --user amnesiac --ssl
# or
./fetchmail -cv unimail.tu-dortmund.de -pimap --auth ssh -v --ssl

I see that you pushed a fix in 6a5484e03e903d3e74d7b6ca8927d616548a6d8c regarding the incorrect retrying of the non-blocking socket. You will be pleased to know that this is fixed in #4807 and will be included in the next fix.

[mandree]

Hi @mandree, I have compiled and tried running the version of fetchmail you specified (e7ee3344792931d8d9439cc0f79dbcc726580187) with wolfSSL but I am receiving the error that I am not logged in. Is it possible for you to provide the full logs to support@wolfssl.com?

Hi Juliusz,

You do not need to be able to log in to see the error. Just trying to negotiate a TLS 1.3 session with fetchmail will be sufficient.

I see that you pushed a fix in 6a5484e03e903d3e74d7b6ca8927d616548a6d8c regarding the incorrect retrying of the non-blocking socket. You will be pleased to know that this is fixed in #4807 and will be included in the next fix.

NOTE: it is critically required to git revert 6a5484e03 8128beadf else fetchmail will mask the bug and you cannot use it as platform to debug wolfSSL. I cannot build your stunnel-5.61 branch to see though,

../src/ssl.c: In function 'wolfSSL_PEM_X509_INFO_read_bio':
../src/ssl.c:45467:17: error: 'else' without a previous 'if'
45467 |                 else {
      |                 ^~~~
../src/ssl.c: In function 'wolfSSL_SESSION_get_ex_new_index':
../src/ssl.c:48347:12: warning: implicit declaration of function 'get_ex_new_index'; did you mean 'SSL_get_ex_new_index'? [-Wimplicit-function-declaration]
48347 |     return get_ex_new_index(CRYPTO_EX_INDEX_SSL_SESSION);
      |            ^~~~~~~~~~~~~~~~
      |            SSL_get_ex_new_index
../src/ssl.c:48347:12: warning: nested extern declaration of 'get_ex_new_index' [-Wnested-externs]

I am trying this wolfSSL:

* 9d1d93f6b 2022-02-01 | Access to session cache is now atomic (HEAD -> stunnel-5.61, origin/stunnel-5.61) [Juliusz Sosinowicz]
* 6874a8d55 2022-01-28 | stunnel 5.61 support [Juliusz Sosinowicz]
*   1465f99b1 2022-01-27 | Merge pull request #4734 from haydenroche5/fips_v5_des3 [John Safranek]
|\  
| * 58789991f 2022-01-24 | Allow DES3 with FIPS v5-dev. [Hayden Roche]
* |   667009007 2022-01-27 | Merge pull request #4799 from SparkiDev/file_gen_fixes [David Garske]
|\ \  
| * | a242424ab 2022-01-27 | Generated files: fixes [Sean Parkinson]
* | |   77a64d008 2022-01-27 | Merge pull request #4802 from SparkiDev/ecies_compressed [David Garske]

[julek-wolfssl]

Hi @mandree,

thank you for your patience. I think that I have finally replicated your error. wolfSSL is returning a WOLFSSL_ERROR_WANT_READ because the fetchmail client has received and processed a session ticket message instead of application data. When we receive a handshake message when peaking we return the WOLFSSL_ERROR_WANT_READ error. To not return that error while peeking, you can define WOLFSSL_TLS13_NO_PEEK_HANDSHAKE_DONE when building wolfSSL. I will make sure to add this to the defines turned on with OPENSSL_COMPATIBLE_DEFAULTS.

[mandree]

@julek-wolfssl Thank you. Could you let me know (I guess Github will do that implicitly) once committed?

My expectation is that if I am using the OpenSSL API, and my application calls SSL_CTX_set_mode(...SSL_MODE_AUTO_RETRY...) that the application will never see SSL_ERROR_WANT_READ on blocking stream (TCP socket) I/O.

[julek-wolfssl]

@mandree I will let you know. Its difficult to follow all the possible paths taken in OpenSSL, but in my understanding, SSL_read will return 0 with the error set to 0 when no data is available to read. Is that what you have found as well? From what I understand in OpenSSL, SSL_MODE_AUTO_RETRY only retries automatically on handshake messages and not on regular application data.

[julek-wolfssl]

@mandree I added the WOLFSSL_TLS13_NO_PEEK_HANDSHAKE_DONE define as part of the fixes in #4807. It will be in the master wolfSSL branch once that pull request gets merged.

[julek-wolfssl]

Hi @mandree, #4807 has been merged. Is there anything else you would like to address in this issue?

[julek-wolfssl]

@mandree I'm closing this issue for now. Feel free to open if you feel this matter is not resolved.
Juliusz

[mandree]

Ah well, what can I say. Branch master, commit a9cc1ca, still breaks... same way.

OK, I admit I am playing dumb here, and do NOT #define OPENSSL_COMPATIBLE_DEFAULTS.
If wolfSSL claims an OpenSSL drop-in compatible interface, it will just have to define OPENSSL_COMPATIBLE_DEFAULTS by itself when an application pulls in the OpenSSL-compatible headers, for instance, openssl/ssl.h.

And do note if I run ../configure '-C' '--enable-debug' '--enable-opensslall' '--enable-harden' '--prefix=/tmp/ws-ocd' CFLAGS="-O2 -DOPENSSL_COMPATIBLE_DEFAULTS -g" && make -j24 check then I get FAIL: scripts/unit.test

[julek-wolfssl]

@mandree Thanks you for this new report. This is a "harmless" bug where we were expecting a failure but succeeding due to the behaviour of OPENSSL_COMPATIBLE_DEFAULTS. I posted a fix here #4936.