Dexador started automatically retry bad requests, but previosly didn't

[svetlyak40wt]

The problem only occur when dexador:*use-connection-pool* is t and there was a connection in the pool.

Here is how to reproduce this problem. We are running a webserver which always responds with HTTP 400 error. And dexador does two requests to the /error URL and signals bad-error only after the second one:

CL-USER> (ql:quickload :dexador-test)

CL-USER> (let ((num-error-calls 0))
           (dexador-test::testing-app "test-retries"
               (lambda (env)
                 (cond
                   ((string= (getf env :path-info)
                             "/error")
                    (incf num-error-calls)
                    '(400 nil ("request failed")))
                   (t
                    '(200 nil ("ok")))))
             (let ((dexador:*use-connection-pool* t))
               (dex:get (clack.test:localhost "/"))
               (dex:get (clack.test:localhost "/error"))))
           num-error-calls)
test-retries
  × 5) Raise an error while testing.
2 (2 bits, #x2, #o2, #b10)

Here, first call to / is just to populate the connection pool. With empty pool dexador behaves as expected fetching /error only once.

This bug is absent in dexador version from Quicklisp dist 2022-04-01, but it is found in Quicklisp 2022-07-08 and latest version of Ultralisp.

P.S. – I'm already working on a fix. Will provide it today.

[svetlyak40wt]

This issue also caused connection pool flooding with connections to the same host and port:

DEXADOR-TEST> (dex:clear-connection-pool)

DEXADOR-TEST> (loop for url in (list "https://httpbin.org/status/200"
                                     "https://httpbin.org/status/400")
                    do (format t "Fetching ~A~%" url)
                       (dex:get url))
Fetching https://httpbin.org/status/200
Fetching https://httpbin.org/status/400
; Debugger entered on #<DEXADOR.ERROR:HTTP-REQUEST-BAD-REQUEST {1018E5DC03}>

DEXADOR-TEST> dex:*connection-pool*
#<DEXADOR.CONNECTION-CACHE::LRU-POOL 2/8 elts
 https://httpbin.org: #<SSL-STREAM for #<FD-STREAM for "socket 10.128.0.30:49204, peer: 54.236.79.58:443" {1018E5A453}>>
 https://httpbin.org: #<SSL-STREAM for #<FD-STREAM for "socket 10.128.0.30:49204, peer: 54.236.79.58:443" {1018E5A453}>>>

DEXADOR-TEST> (loop for url in (list "https://httpbin.org/status/200"
                                     "https://httpbin.org/status/400")
                    do (format t "Fetching ~A~%" url)
                       (dex:get url))
Fetching https://httpbin.org/status/200
Fetching https://httpbin.org/status/400
; Debugger entered on #<DEXADOR.ERROR:HTTP-REQUEST-BAD-REQUEST {10190650D3}>
[1] DEXADOR-TEST>
; Evaluation aborted on #<DEXADOR.ERROR:HTTP-REQUEST-BAD-REQUEST {10190650D3}>

DEXADOR-TEST> dex:*connection-pool*
#<DEXADOR.CONNECTION-CACHE::LRU-POOL 3/8 elts
 https://httpbin.org: #<SSL-STREAM for #<FD-STREAM for "socket 10.128.0.30:49204, peer: 54.236.79.58:443" {1018E5A453}>>
 https://httpbin.org: #<SSL-STREAM for #<FD-STREAM for "socket 10.128.0.30:49208, peer: 54.236.79.58:443" {1019061923}>>
 https://httpbin.org: #<SSL-STREAM for #<FD-STREAM for "socket 10.128.0.30:49208, peer: 54.236.79.58:443" {1019061923}>>>

DEXADOR-TEST> (loop for url in (list "https://httpbin.org/status/200"
                                     "https://httpbin.org/status/400")
                    do (format t "Fetching ~A~%" url)
                       (dex:get url))
Fetching https://httpbin.org/status/200
Fetching https://httpbin.org/status/400
; Debugger entered on #<DEXADOR.ERROR:HTTP-REQUEST-BAD-REQUEST {1019264A83}>

DEXADOR-TEST> dex:*connection-pool*
#<DEXADOR.CONNECTION-CACHE::LRU-POOL 4/8 elts
 https://httpbin.org: #<SSL-STREAM for #<FD-STREAM for "socket 10.128.0.30:49204, peer: 54.236.79.58:443" {1018E5A453}>>
 https://httpbin.org: #<SSL-STREAM for #<FD-STREAM for "socket 10.128.0.30:49208, peer: 54.236.79.58:443" {1019061923}>>
 https://httpbin.org: #<SSL-STREAM for #<FD-STREAM for "socket 10.128.0.30:49212, peer: 54.236.79.58:443" {10192612D3}>>
 https://httpbin.org: #<SSL-STREAM for #<FD-STREAM for "socket 10.128.0.30:49212, peer: 54.236.79.58:443" {10192612D3}>>>

[svetlyak40wt]

And in cases if server requests Connection: close on error (as GitHub does), this issue caused that closed connection was used on 400 error retry and lead to output operation on closed SSL stream error. Here is how to reproduce it:

DEXADOR-TEST> dex:*connection-pool*
#<DEXADOR.CONNECTION-CACHE::LRU-POOL empty>

DEXADOR-TEST> (loop for url in (list "https://raw.githubusercontent.com/40ants/ci/master/.github/workflows/ci.yml"
                                     "https://raw.githubusercontent.com/40ants/ci/master/Build Failed")
                    do (format t "Fetching ~A~%" url)
                       (dex:get url))
Fetching https://raw.githubusercontent.com/40ants/ci/master/.github/workflows/ci.yml
Fetching https://raw.githubusercontent.com/40ants/ci/master/Build Failed
; Debugger entered on #<SIMPLE-ERROR "output operation on closed SSL stream" {10185DAC53}>

DEXADOR-TEST> dex:*connection-pool*
#<DEXADOR.CONNECTION-CACHE::LRU-POOL empty>

[svetlyak40wt]

Here is the fix:

https://github.com/fukamachi/dexador/pull/138