[Bug 46127] New: aria2 1.34 fails to connect, reports 'WinTLS: Channel setup failed. Schannel provider did not fulfill requested flags. Excepted : 33180 Actual: 33052'

wine-bugs at winehq.org wine-bugs at winehq.org
Sun Nov 11 08:54:25 CST 2018 

https://bugs.winehq.org/show_bug.cgi?id=46127

            Bug ID: 46127
           Summary: aria2 1.34 fails to connect, reports 'WinTLS: Channel
                    setup failed. Schannel provider did not fulfill
                    requested flags. Excepted: 33180 Actual: 33052'
           Product: Wine
           Version: 3.20
          Hardware: x86-64
                OS: Linux
            Status: NEW
          Severity: normal
          Priority: P2
         Component: secur32
          Assignee: wine-bugs at winehq.org
          Reporter: focht at gmx.net
      Distribution: ---

Hello folks,

as it says. Website: https://aria2.github.io/

--- quote ---
aria2 is a lightweight multi-protocol & multi-source command-line download
utility. It supports HTTP/HTTPS, FTP, SFTP, BitTorrent and Metalink. aria2 can
be manipulated via built-in JSON-RPC and XML-RPC interfaces.
--- quote ---

Also reported on their Github, but likely with old Wine version which suffered
at that time from another insufficiency in related area.

https://github.com/aria2/aria2/issues/348

--- quote ---
You could always build aria2 on your own using the OpenSSL or GnuTLS TLS
backend instead of WinTLS... Or use a linux build in the first place...

It seems to me that wine's Schannel implementation is incomplete or buggy, and
seeing that this affects the context state flags, working around this would
require not checking the channel integrity at all... Which might be actually an
option for the --check-certificate=false case. Need to ponder on this.
--- quote ---

Trace log:

--- snip ---
$ WINEDEBUG=+seh,+relay,+bcrypt,+secur32 wine64 ./aria2c_x64.exe
"https://uup.rg-adguard.net/api/GetFiles?id=foobar" >>log.txt 2>&1
...
002e:Call secur32.InitializeSecurityContextA(008f3710,00000000,008f3570
"uup.rg-adguard.net",0000819c,00000000,00000000,00000000,69cb2f8700000000,008e5570,0033efd0,0033ef6c,00000000)
ret=00466d4b
002e:trace:secur32:InitializeSecurityContextA 0x8f3710 (nil)
"uup.rg-adguard.net" 0x0000819c 0 0 (nil) 0 0x8e5570 0x33efd0 0x33ef6c (nil)
002e:trace:secur32:schan_InitializeSecurityContextA 0x8a320 (nil)
"uup.rg-adguard.net" 33180 0 0 (nil) 0 0x33ed40 0x33efd0 0x33ef6c (nil)
...
002e:trace:secur32:schan_InitializeSecurityContextW 0x8a320 (nil)
L"uup.rg-adguard.net" 0x0000819c 0 0 (nil) 0 0x33ed40 0x33efd0 0x33ef6c (nil)
002e:trace:secur32:dump_buffer_desc Buffer desc 0x33efd0:
002e:trace:secur32:dump_buffer_desc     buffer 0: cbBuffer 0, BufferType 0
pvBuffer (nil)
...
002e:trace:secur32:schan_imp_create_session Using
"NORMAL:%LATEST_RECORD_VERSION:+VERS-TLS1.2:+VERS-TLS1.1:+VERS-TLS1.0:-VERS-SSL3.0"
priority
002e:trace:secur32:schan_gnutls_log <2> added 5 protocols, 29 ciphersuites, 15
sig algos and 9 groups into priority list
...
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: Adv. version: 3.3
...
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: CLIENT HELLO was
queued [220 bytes]
002e:trace:secur32:schan_push Push 225 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 0, BufferType 0x2,
pvBuffer (nil)
002e:Call ntdll.RtlAllocateHeap(00010000,00000000,00000100) ret=7f1c611a498b
002e:Ret  ntdll.RtlAllocateHeap() retval=0008b300 ret=7f1c611a498b
002e:trace:secur32:schan_push Wrote 225 bytes
002e:trace:secur32:schan_gnutls_log <3> ASSERT: buffers.c[get_last_packet]:1171
002e:trace:secur32:schan_pull Pull 5 bytes
002e:trace:secur32:schan_get_buffer No desc
002e:trace:secur32:schan_gnutls_log <3> ASSERT:
buffers.c[_gnutls_io_read_buffered]:589
002e:trace:secur32:schan_imp_handshake Continue...
...
002e:Ret  secur32.InitializeSecurityContextA() retval=00090312 ret=00466d4b
...
002e:Call secur32.InitializeSecurityContextA(008f3710,008e5570,008f3570
"uup.rg-adguard.net",0000819c,00000000,00000000,0033ef70,00000000,00000000,0033ef80,0033ef6c,00000000)
ret=00467035
002e:trace:secur32:InitializeSecurityContextA 0x8f3710 0x8e5570
"uup.rg-adguard.net" 0x0000819c 0 0 0x33ef70 0 (nil) 0x33ef80 0x33ef6c (nil)
002e:trace:secur32:schan_InitializeSecurityContextA 0x8a320 0x8a350
"uup.rg-adguard.net" 33180 0 0 0x33ef70 0 (nil) 0x33ef80 0x33ef6c (nil)
...
002e:trace:secur32:schan_InitializeSecurityContextW 0x8a320 0x8a350
L"uup.rg-adguard.net" 0x0000819c 0 0 0x33ef70 0 (nil) 0x33ef80 0x33ef6c (nil)
002e:trace:secur32:dump_buffer_desc Buffer desc 0x33ef70:
002e:trace:secur32:dump_buffer_desc     buffer 0: cbBuffer 3187, BufferType 0x2
pvBuffer 0x8e66c0
002e:trace:secur32:dump_buffer_desc     buffer 1: cbBuffer 0, BufferType 0
pvBuffer (nil)
002e:trace:secur32:dump_buffer_desc Buffer desc 0x33ef80:
002e:trace:secur32:dump_buffer_desc     buffer 0: cbBuffer 0, BufferType 0x2
pvBuffer (nil)
002e:trace:secur32:dump_buffer_desc     buffer 1: cbBuffer 0, BufferType 0x11
pvBuffer (nil)
002e:trace:secur32:schan_InitializeSecurityContextW Using expected_size 3187.
002e:trace:secur32:schan_gnutls_log <3> ASSERT: buffers.c[get_last_packet]:1171
002e:trace:secur32:schan_pull Pull 5 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 3187, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 5 bytes
002e:trace:secur32:schan_pull Pull 65 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 3187, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 65 bytes
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: SERVER HELLO (2) was
received. Length 61[61], frag offset 0, frag length: 61, sequence: 0
002e:trace:secur32:schan_gnutls_log <3> ASSERT: buffers.c[get_last_packet]:1162
002e:trace:secur32:schan_gnutls_log <3> ASSERT:
buffers.c[_gnutls_handshake_io_recv_int]:1413
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: Server's version: 3.3
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: SessionID length: 0
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: SessionID: c0
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: Selected cipher suite:
GNUTLS_ECDHE_RSA_AES_128_GCM_SHA256
002e:trace:secur32:schan_gnutls_log <4> EXT[0x7d673980]: Parsing extension
'Server Name Indication/0' (0 bytes)
002e:trace:secur32:schan_gnutls_log <4> EXT[0x7d673980]: Parsing extension
'Safe Renegotiation/65281' (1 bytes)
002e:trace:secur32:schan_gnutls_log <4> EXT[0x7d673980]: Parsing extension
'Supported EC Point Formats/11' (4 bytes)
002e:trace:secur32:schan_gnutls_log <4> EXT[0x7d673980]: Parsing extension
'Session Ticket/35' (0 bytes)
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: Safe renegotiation
succeeded
002e:trace:secur32:schan_gnutls_log <3> ASSERT: buffers.c[get_last_packet]:1171
002e:trace:secur32:schan_pull Pull 5 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 3187, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 5 bytes
002e:trace:secur32:schan_pull Pull 2765 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 3187, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 2765 bytes
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: CERTIFICATE (11) was
received. Length 2761[2761], frag offset 0, frag length: 2761, sequence: 0
002e:trace:secur32:schan_gnutls_log <3> ASSERT: buffers.c[get_last_packet]:1171
002e:trace:secur32:schan_pull Pull 5 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 3187, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 5 bytes
002e:trace:secur32:schan_pull Pull 333 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 3187, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 333 bytes
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: SERVER KEY EXCHANGE
(12) was received. Length 329[329], frag offset 0, frag length: 329, sequence:
0
002e:trace:secur32:schan_gnutls_log <2> received curve SECP256R1
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: Selected group
SECP256R1 (2)
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: verify TLS 1.2
handshake data: using RSA-SHA512
002e:trace:secur32:schan_gnutls_log <3> ASSERT: buffers.c[get_last_packet]:1171
002e:trace:secur32:schan_pull Pull 5 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 3187, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 5 bytes
002e:trace:secur32:schan_pull Pull 4 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 3187, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 4 bytes
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: SERVER HELLO DONE (14)
was received. Length 0[0], frag offset 0, frag length: 0, sequence: 0
002e:trace:secur32:schan_gnutls_log <3> ASSERT: buffers.c[get_last_packet]:1162
002e:trace:secur32:schan_gnutls_log <3> ASSERT:
buffers.c[_gnutls_handshake_io_recv_int]:1413
002e:trace:secur32:schan_gnutls_log <3> ASSERT: mpi.c[wrap_nettle_mpi_print]:60
002e:trace:secur32:schan_gnutls_log <3> ASSERT: mpi.c[wrap_nettle_mpi_print]:60
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: CLIENT KEY EXCHANGE
was queued [70 bytes]
002e:trace:secur32:schan_gnutls_log <4> REC[0x7d673980]: Sent ChangeCipherSpec
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: Cipher Suite:
GNUTLS_ECDHE_RSA_AES_128_GCM_SHA256
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: Initializing internal
[write] cipher sessions
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: recording tls-unique
CB (send)
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: FINISHED was queued
[16 bytes]
002e:trace:secur32:schan_push Push 75 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 0, BufferType 0x2,
pvBuffer (nil)
002e:Call ntdll.RtlAllocateHeap(00010000,00000000,00000080) ret=7f1c611a498b
002e:Ret  ntdll.RtlAllocateHeap() retval=0008b300 ret=7f1c611a498b
002e:trace:secur32:schan_push Wrote 75 bytes
002e:trace:secur32:schan_push Push 6 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 128, BufferType
0x2, pvBuffer 0x8b300
002e:trace:secur32:schan_push Wrote 6 bytes
002e:trace:secur32:schan_push Push 45 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 128, BufferType
0x2, pvBuffer 0x8b300
002e:trace:secur32:schan_push Wrote 45 bytes
002e:trace:secur32:schan_gnutls_log <3> ASSERT: buffers.c[get_last_packet]:1171
002e:trace:secur32:schan_pull Pull 5 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 3187, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_get_buffer No next buffer
002e:trace:secur32:schan_gnutls_log <3> ASSERT:
buffers.c[_gnutls_io_read_buffered]:589
002e:trace:secur32:schan_imp_handshake Continue...
...
002e:Ret  secur32.InitializeSecurityContextA() retval=00090312 ret=00467035
...
002e:Call secur32.InitializeSecurityContextA(008f3710,008e5570,008f3570
"uup.rg-adguard.net",0000819c,00000000,00000000,0033ef70,00000000,00000000,0033ef80,0033ef6c,00000000)
ret=00467035
002e:trace:secur32:InitializeSecurityContextA 0x8f3710 0x8e5570
"uup.rg-adguard.net" 0x0000819c 0 0 0x33ef70 0 (nil) 0x33ef80 0x33ef6c (nil)
002e:trace:secur32:schan_InitializeSecurityContextA 0x8a320 0x8a350
"uup.rg-adguard.net" 33180 0 0 0x33ef70 0 (nil) 0x33ef80 0x33ef6c (nil)
...
002e:trace:secur32:schan_InitializeSecurityContextW 0x8a320 0x8a350
L"uup.rg-adguard.net" 0x0000819c 0 0 0x33ef70 0 (nil) 0x33ef80 0x33ef6c (nil)
002e:trace:secur32:dump_buffer_desc Buffer desc 0x33ef70:
002e:trace:secur32:dump_buffer_desc     buffer 0: cbBuffer 258, BufferType 0x2
pvBuffer 0x8e66c0
002e:trace:secur32:dump_buffer_desc     buffer 1: cbBuffer 0, BufferType 0
pvBuffer (nil)
002e:trace:secur32:dump_buffer_desc Buffer desc 0x33ef80:
002e:trace:secur32:dump_buffer_desc     buffer 0: cbBuffer 0, BufferType 0x2
pvBuffer (nil)
002e:trace:secur32:dump_buffer_desc     buffer 1: cbBuffer 0, BufferType 0x11
pvBuffer (nil)
002e:trace:secur32:schan_InitializeSecurityContextW Using expected_size 258.
002e:trace:secur32:schan_gnutls_log <3> ASSERT: buffers.c[get_last_packet]:1171
002e:trace:secur32:schan_pull Pull 5 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 258, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 5 bytes
002e:trace:secur32:schan_pull Pull 202 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 258, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 202 bytes
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: NEW SESSION TICKET (4)
was received. Length 198[198], frag offset 0, frag length: 198, sequence: 0
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: received session
ticket
002e:trace:secur32:schan_pull Pull 5 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 258, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 5 bytes
002e:trace:secur32:schan_pull Pull 1 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 258, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 1 bytes
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: Cipher Suite:
GNUTLS_ECDHE_RSA_AES_128_GCM_SHA256
002e:trace:secur32:schan_gnutls_log <3> ASSERT: buffers.c[get_last_packet]:1171
002e:trace:secur32:schan_pull Pull 5 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 258, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 5 bytes
002e:trace:secur32:schan_pull Pull 40 bytes
002e:trace:secur32:schan_get_buffer Using buffer 0: cbBuffer 258, BufferType
0x2, pvBuffer 0x8e66c0
002e:trace:secur32:schan_pull Read 40 bytes
002e:trace:secur32:schan_gnutls_log <4> HSK[0x7d673980]: FINISHED (20) was
received. Length 12[12], frag offset 0, frag length: 12, sequence: 0
002e:trace:secur32:schan_imp_handshake Handshake completed
002e:Call ntdll.RtlFreeHeap(00010000,00000000,0008aea0) ret=7f1c611a3d55
002e:Ret  ntdll.RtlFreeHeap() retval=00000001 ret=7f1c611a3d55
002e:Ret  secur32.InitializeSecurityContextA() retval=00000000 ret=00467035
...
002e:Call msvcrt.strlen(008f35a0 "WinTLS: Channel setup failed. Schannel
provider did not fulfill requested flags. Excepted: 33180 Actual: 33052")
ret=006b27b5 
--- snip ---

App source:

https://github.com/aria2/aria2/blob/475e6c59970c95561ca9eb6b4a02fb54ec4a91fc/src/WinTLSSession.cc#L575

--- snip ---
static const ULONG kReqFlags =
    ISC_REQ_SEQUENCE_DETECT | ISC_REQ_REPLAY_DETECT | ISC_REQ_CONFIDENTIALITY |
    ISC_REQ_ALLOCATE_MEMORY | ISC_REQ_USE_SUPPLIED_CREDS | ISC_REQ_STREAM;

static const ULONG kReqAFlags =
    ASC_REQ_SEQUENCE_DETECT | ASC_REQ_REPLAY_DETECT | ASC_REQ_CONFIDENTIALITY |
ASC_REQ_EXTENDED_ERROR | ASC_REQ_ALLOCATE_MEMORY | ASC_REQ_STREAM;

...

int WinTLSSession::tlsConnect(const std::string& hostname, TLSVersion& version,
                              std::string& handshakeErr)
{
  // Handshaking will require sending multiple read/write exchanges until the
  // handshake is actually done. The client will first generate the initial
  // handshake message, then write that to the server, read the response
  // message, and write and/or read additional messages until the handshake is
  // either complete and successful, or something went wrong.
  // The server works analog to that.

  A2_LOG_DEBUG("WinTLS: Starting/Resuming TLS Connect");
ULONG flags = 0;
...
    if (side_ == TLS_CLIENT) {
      SEC_CHAR* host = hostname_.empty()
                           ? nullptr
                           : const_cast<SEC_CHAR*>(hostname_.c_str());
      status_ = ::InitializeSecurityContext(cred_, &handle_, host, kReqFlags,
0,
                                            0, &indesc, 0, nullptr, &outdesc,
                                            &flags, nullptr);
    }
    else {
      status_ = ::AcceptSecurityContext(
          cred_, state_ == st_initialized ? nullptr : &handle_, &indesc,
          kReqAFlags, 0, state_ == st_initialized ? &handle_ : nullptr,
          &outdesc, &flags, nullptr);
    }
...
    // Need to read additional messages?
    if (status_ == SEC_I_CONTINUE_NEEDED) {
      A2_LOG_DEBUG("WinTLS: Continuing with handshake");
      goto restart;
    }

    if (side_ == TLS_CLIENT && flags != kReqFlags) {
      A2_LOG_ERROR(fmt("WinTLS: Channel setup failed. Schannel provider did "
                       "not fulfill requested flags. "
                       "Excepted: %lu Actual: %lu",
                       kReqFlags, flags));
      status_ = SEC_E_INTERNAL_ERROR;
      state_ = st_error;
      return TLS_ERR_ERROR;
    }
...
--- snip ---

>From out flags missing: 'ISC_REQ_USE_SUPPLIED_CREDS'

Wine source:

https://source.winehq.org/git/wine.git/blob/HEAD:/include/sspi.h#l330

https://source.winehq.org/git/wine.git/blob/HEAD:/dlls/secur32/schannel.c#l784

$ sha1sum aria2_install.zip 
105e5b3f46c482ded5b6cfa5ae94cd2af353b07a  aria2_install.zip

$ du -sh aria2_install.zip 
4.0M    aria2_install.zip

$ wine --version
wine-3.20-7-ga0a7090301

Regards

-- 
Do not reply to this email, post in Bugzilla using the
above URL to reply.
You are receiving this mail because:
You are watching all bug changes.

More information about the wine-bugs mailing list