Read-timeout does not work on SBCL and ClozureCL

[svetlyak40wt]

Here is the code to reproduce:

CL-USER> (time (nth-value 1 (dex:get "https://httpbin.org/delay/10" :read-timeout 2)))
Evaluation took:
  10.553 seconds of real time
  0.056000 seconds of total run time (0.052000 user, 0.004000 system)

Url https://httpbin.org/delay/10 respond in 10 seconds, but I expect dex:get signal error after the 2 seconds.

If network flaps, this leads to situations where requests are hanging forever.

Argument :read-timeout was added in this pull https://github.com/fukamachi/dexador/pull/71/files. It calls (usocket:socket-option connection :receive-timeout) method for a new socket, which has implementation for SBCL and ClozureCL, the lisps I'm tested this option:

https://github.com/usocket/usocket/blob/820e760abae25471d0f90d50e8e306d31a132852/option.lisp#L42

I was able to reproduce this bug on:

• SBCL 2.0.5 Linux
• SBCL 2.0.8 OSX
• ClozureCL 1.12-dev (v1.12-dev.5) OSX

[lispstudent]

If it can be of help, same test on LispWorks (Windows) times out after about 3.5 seconds:

CL-USER 9 > (time (nth-value 1 (dex:get "https://httpbin.org/delay/10" :read-timeout 2)))
Timing the evaluation of (NTH-VALUE 1 (DEXADOR:GET "https://httpbin.org/delay/10" :READ-TIMEOUT 2))

Error: ERROR 12002: Timeout
  1 (abort) Return to top loop level 0.

Type :b for backtrace or :c <option number> to proceed.
Type :bug-form "<subject>" for a bug report template or :? for other options.

CL-USER 10 : 1 > 
User time    =        0.000
System time  =        0.000
Elapsed time =        3.838
Allocation   = 140008 bytes
0 Page faults

[ajberkley]

I will work on correcting the implementation of this in cl+ssl. Then if I am still happy, will add to dexador and drakma.

[avodonosov]

Currently this problem can be worked-around like this:

(let ((cl+ssl:*default-unwrap-stream-p* nil))
  (time (nth-value 1 (dex:get "https://httpbin.org/delay/10" :read-timeout 2))))

After two seconds I have (on CCL):

A failure in the SSL library occurred on handle #<A Foreign Pointer #x7FE3400B2DF0> (return code: 1). ERR_print_errors(): 140614316242688:error:01000044:unknown library:unknown library:internal error:cl+ssl/src/bio.lisp:0:Unexpected SERIOUS-CONDITION in the Lisp BIO: Input timeout on #<BASIC-TCP-STREAM ISO-8859-1 (SOCKET/4) #x3020027F4ACD>
   [Condition of type CL+SSL::SSL-ERROR-SSL]

Backtrace:
  0: (CL+SSL::SSL-SIGNAL-ERROR #<A Foreign Pointer #x7FE3400B2DF0> #<Compiled-function CL+SSL::SSL-READ #x30200180772F> 1 -1)
  1: (#<STANDARD-METHOD STREAM-READ-BYTE (CL+SSL::SSL-STREAM)> #<SSL-STREAM for #<BASIC-TCP-STREAM :CLOSED #x3020027F4ACD>>)
  2: (READ-BYTE #<SSL-STREAM for #<BASIC-TCP-STREAM :CLOSED #x3020027F4ACD>> NIL NIL)
  3: (DEXADOR.BACKEND.USOCKET::READ-UNTIL-CRLF*2 #<SSL-STREAM for #<BASIC-TCP-STREAM :CLOSED #x3020027F4ACD>>)
  4: (DEXADOR.BACKEND.USOCKET::READ-RESPONSE #<SSL-STREAM for #<BASIC-TCP-STREAM :CLOSED #x3020027F4ACD>> T NIL T)
  5: (DEXADOR.BACKEND.USOCKET:REQUEST "https://httpbin.org/delay/10" :METHOD :GET :READ-TIMEOUT 2)
  6: (#<Anonymous Function #x3020027F93FF>)
  7: (CCL::REPORT-TIME (NTH-VALUE 1 (DEXADOR:GET "https://httpbin.org/delay/10" :READ-TIMEOUT 2)) #<Anonymous Function #x3020027F93FF>)

This works because the *default-unwrap-stream-p* nil makes cl+ssl delegate all the low-level (unencrypted) IO to the lisp stream of the socket - cl+ssl uses custom Lisp BIO in this case. And the Lisp stream has timeout configured by dexador.

In the default mode cl+ssl extracts socket file descriptor from lisp stream, and passes it to OpenSSL to perform IO using the normal OpenSSL's socket BIO. And the socket file descriptor does not know about the timeout set on the Lisp stream level.