Failing when requesting localhost

[K1D77A]

Hi, this is a bug I keep experiencing. I have a ningle server running on 0.0.0.0 and I'm using dex:post to test my APIs, however every now and then dex fails with the following stack trace:

The value
  NIL
is not of type
  SB-IMPL::BUFFER
   [Condition of type TYPE-ERROR]

Restarts:
 0: [RETRY-REQUEST] Retry the same request.
 1: [IGNORE-AND-CONTINUE] Ignore the error and continue.
 2: [RETRY] Retry SLY mREPL evaluation request.
 3: [*ABORT] Return to SLY's top level.
 4: [ABORT] abort thread (#<THREAD "sly-channel-1-mrepl-remote-1" RUNNING {10018042F3}>)

Backtrace:
 0: (SB-IMPL::BUFFER-OUTPUT #<SB-SYS:FD-STREAM for "socket 127.0.0.1:60846, peer: 127.0.0.1:43333" {1016E0ECA3}> #(80 79 83 84 32 47 ...) 0 104)
      Locals:
        END = 104
        START = 0
        STREAM = #<SB-SYS:FD-STREAM for "socket 127.0.0.1:60846, peer: 127.0.0.1:43333" {1016E0ECA3}>
        THING = #(80 79 83 84 32 47 118 49 47 115 101 114 118 105 99 101 47 33 99 115 54 48 98 121 102 57 101 121 115 121 112 105 101 117 117 100 52 105 102 101 99 111 112 122 109 121 109 55 53 56 98 111 102 112 50 ..)
 1: (SB-IMPL::WRITE-SEQ-IMPL #(80 79 83 84 32 47 ...) #<SB-SYS:FD-STREAM for "socket 127.0.0.1:60846, peer: 127.0.0.1:43333" {1016E0ECA3}> 0 NIL)
      Locals:
        %END = NIL
        SEQ = #(80 79 83 84 32 47 118 49 47 115 101 114 118 105 99 101 47 33 99 115 54 48 98 121 102 57 101 121 115 121 112 105 101 117 117 100 52 105 102 101 99 111 112 122 109 121 109 55 53 56 98 111 102 112 50 ..)
        START = 0
        STREAM = #<SB-SYS:FD-STREAM for "socket 127.0.0.1:60846, peer: 127.0.0.1:43333" {1016E0ECA3}>
 2: (WRITE-SEQUENCE #(80 79 83 84 32 47 ...) #<SB-SYS:FD-STREAM for "socket 127.0.0.1:60846, peer: 127.0.0.1:43333" {1016E0ECA3}> :START 0 :END NIL)
      Locals:
        #:.DEFAULTING-TEMP. = 0
        #:.DEFAULTING-TEMP.#1 = NIL
        SB-IMPL::SEQ = #(80 79 83 84 32 47 118 49 47 115 101 114 118 105 99 101 47 33 99 115 54 48 98 121 102 57 101 121 115 121 112 105 101 117 117 100 52 105 102 101 99 111 112 122 109 121 109 55 53 56 98 111 102 112 50 ..)
        STREAM = #<SB-SYS:FD-STREAM for "socket 127.0.0.1:60846, peer: 127.0.0.1:43333" {1016E0ECA3}>
 3: (DEXADOR.BACKEND.USOCKET:REQUEST "http://127.0.

If I repeat the request it works without a problem, until the next time anyway.

I think this is a problem because I am not using https (localhost ofc). If you need anymore info I will help how I can. Thanks.

[ajberkley]

Are you using connection pooling in dex?

The data that is being sent is "POST /v1/service/!..." so this is likely the first thing we are doing on this connection.

I can only see this happening if we are writing to an already closed FD-STREAM.

It would be helpful if you could verify that by inspecting the stream in the debugger.

Some information from the request frame would be useful too... compile with debugging and show what is there (it would maybe tell us if it had grabbed a pooled connection, etc)

[K1D77A]

I am not explicitly disabling connection pooling.

#<SB-SYS:FD-STREAM {1017CCA7E3}>
--------------------
The object is a STRUCTURE-OBJECT of type SB-SYS:FD-STREAM.
IN-BUFFER: NIL
CIN-BUFFER: NIL
IN-INDEX: 512
IN: #<FUNCTION SB-KERNEL:CLOSED-FLAME>
BIN: #<FUNCTION SB-KERNEL:CLOSED-FLAME>
N-BIN: #<FUNCTION SB-KERNEL:CLOSED-FLAME>
OUT: #<FUNCTION SB-KERNEL:CLOSED-FLAME>
BOUT: #<FUNCTION SB-KERNEL:CLOSED-FLAME>
SOUT: #<FUNCTION SB-KERNEL:CLOSED-FLAME>
MISC: #<FUNCTION SB-KERNEL:CLOSED-FLAME>
INPUT-CHAR-POS: NIL
NAME: "socket 127.0.0.1:51620, peer: 127.0.0.1:43333"
FILE: NIL
ORIGINAL: NIL
DELETE-ORIGINAL: NIL
ELEMENT-SIZE: 1
ELEMENT-TYPE: (UNSIGNED-BYTE 8)
ELEMENT-MODE: UNSIGNED-BYTE
FD: 22
FD-TYPE: :SOCKET
BUFFERING: :FULL
DUAL-CHANNEL-P: T
OUTPUT-COLUMN: 0
LISTEN: NIL
SERVE-EVENTS: NIL
INSTEAD: ""
IBUF: NIL
EOF-FORCED-P: NIL
OBUF: NIL
OUTPUT-QUEUE: NIL
HANDLER: NIL
TIMEOUT: 10.0
PATHNAME: NIL
EXTERNAL-FORMAT: :LATIN-1
CHAR-SIZE: 1
OUTPUT-BYTES: #<FUNCTION SB-KERNEL:ILL-OUT>

 3: (DEXADOR.BACKEND.USOCKET:REQUEST "http://127.0.0.1:43333/v1/service/!cs60byf9eysypieuud4ifecopzmym758bofp2ndicwagyzi63qsj6bc61my6d2g/new-payment" :METHOD :POST :CONTENT "{\"AMOUNT\":\"1000\"}" :HEADER..
      Locals:
        #:.DEFAULTING-TEMP. = :POST
        #:.DEFAULTING-TEMP.#1 = 1.1
        #:.DEFAULTING-TEMP.#2 = "{\"AMOUNT\":\"1000\"}"
        #:.DEFAULTING-TEMP.#3 = (("crc" . 3565213847) ("Authorization" . "Bearer apikey-ei2j55kipt3afmzyszrv19ezy1k1dd7d7l5grfvo8icugw652iwc60z534"))
        #:.DEFAULTING-TEMP.#4 = NIL
        #:.DEFAULTING-TEMP.#5 = NIL
        #:.DEFAULTING-TEMP.#6 = NIL
        #:.DEFAULTING-TEMP.#7 = NIL
        #:.DEFAULTING-TEMP.#8 = T
        #:.DEFAULTING-TEMP.#9 = T
        #:.DEFAULTING-TEMP.#10 = 5
        #:.DEFAULTING-TEMP.#11 = NIL
        #:.DEFAULTING-TEMP.#12 = NIL
        #:.DEFAULTING-TEMP.#13 = NIL
        #:.DEFAULTING-TEMP.#14 = NIL
        #:.DEFAULTING-TEMP.#15 = NIL
        #:.DEFAULTING-TEMP.#16 = NIL
        #:.DEFAULTING-TEMP.#17 = NIL
        #:.DEFAULTING-TEMP.#18 = NIL
        #:.DEFAULTING-TEMP.#19 = NIL
        #:.DEFAULTING-TEMP.#20 = NIL
        #:.DEFAULTING-TEMP.#21 = NIL
        ARGS = (:METHOD :POST :CONTENT "{\"AMOUNT\":\"1000\"}" :HEADERS (("crc" . 3565213847) ("Authorization" . "Bearer apikey-ei2j55kipt3afmzyszrv19ezy1k1dd7d7l5grfvo8icugw652iwc60z534")))
        BASIC-AUTH = NIL
        BOUNDARY = NIL
        CA-PATH = NIL
        CHUNKEDP = NIL
        CONNECT-TIMEOUT = 10
        CONTENT = "{\"AMOUNT\":\"1000\"}"
        CONTENT#1 = "{\"AMOUNT\":\"1000\"}"
        CONTENT-LENGTH#3 = NIL
        CONTENT-TYPE = NIL
        COOKIE-HEADERS = NIL
        COOKIE-JAR = NIL
        FIRST-LINE-DATA = #(80 79 83 84 32 47 118 49 47 115 101 114 118 105 99 101 47 33 99 115 54 48 98 121 102 57 101 121 115 121 112 105 101 117 117 100 52 105 102 101 99 111 112 122 109 121 109 55 53 56 98 111 102 112 50 ..)
        FORCE-BINARY = NIL
        FORCE-STRING = NIL
        FORM-URLENCODED-P = NIL
        HEADERS = (("crc" . 3565213847) ("Authorization" . "Bearer apikey-ei2j55kipt3afmzyszrv19ezy1k1dd7d7l5grfvo8icugw652iwc60z534"))
        HEADERS-DATA = #(85 115 101 114 45 65 103 101 110 116 58 32 68 101 120 97 100 111 114 47 48 46 57 46 49 53 32 40 83 66 67 76 32 50 46 50 46 48 41 59 32 76 105 110 117 120 59 32 53 46 49 48 46 48 45 49 52 45 97 109 ..)
        INSECURE = NIL
        KEEP-ALIVE = T
        MAX-REDIRECTS = 5
        METHOD = :POST
        MULTIPART-P = NIL
        #:N-SUPPLIED-2 = 0
        #:N-SUPPLIED-3 = 0
        #:N-SUPPLIED-4 = 0
        #:N-SUPPLIED-5 = 0
        ORIGINAL-USER-SUPPLIED-STREAM = NIL
        PROXY = NIL
        PROXY#1 = NIL
        PROXY-URI = NIL
        READ-TIMEOUT = 10
        REUSING-STREAM-P = NIL
        SSL-CERT-FILE = NIL
        SSL-KEY-FILE = NIL
        SSL-KEY-PASSWORD = NIL
        STREAM#1 = #<SB-SYS:FD-STREAM for "socket 127.0.0.1:51620, peer: 127.0.0.1:43333" {1017CCA7E3}>
        STREAM#2 = #<SB-SYS:FD-STREAM for "socket 127.0.0.1:51620, peer: 127.0.0.1:43333" {1017CCA7E3}>
        STREAM#3 = NIL
        TRANSFER-ENCODING = NIL
        URI = "http://127.0.0.1:43333/v1/service/!cs60byf9eysypieuud4ifecopzmym758bofp2ndicwagyzi63qsj6bc61my6d2g/new-payment"
        URI#2 = #<QURI.URI.HTTP:URI-HTTP http://127.0.0.1:43333/v1/service/!cs60byf9eysypieuud4ifecopzmym758bofp2ndicwagyzi63qsj6bc61my6d2g/new-payment>
        USE-CONNECTION-POOL = T
        USER-SUPPLIED-STREAM = NIL
        VERBOSE = NIL
        VERSION = 1.1
        WANT-STREAM = NIL

[ajberkley]

So if the stream is already closed, we should be getting a closed-stream-error, not this internal error... so it's a bit confusing. The only way to get around that I think is for close to be called on this stream while we are actively using it. This is designed not to happen but I guess in some of the finalizer shenanigans we get up to there could be a bug.

[ajberkley]

So reusing-stream-p is nil, which means this connection didn't come from the connection pool...

[K1D77A]

  0: (ERROR SB-INT:BROKEN-PIPE :STREAM #<SB-SYS:FD-STREAM for "socket 127.0.0.1:51620, peer: 127.0.0.1:43333" {1017CCA7E3}> :FORMAT-CONTROL "~@<~?~@[: ~2I~_~A~]~:>" :FORMAT-ARGUMENTS ("Couldn't write to ~S" (#<SB-SYS:FD-STREAM for "socket 127.0.0.1:51620, peer: 127.0.0.1:43333" {1017CCA7E3}>) "Broken pipe"))
  0: (ERROR TYPE-ERROR :DATUM NIL :EXPECTED-TYPE SB-IMPL::BUFFER :CONTEXT NIL)
; Debugger entered on #<TYPE-ERROR expected-type: SB-IMPL::BUFFER datum: NIL>
    1: (ERROR "~@<The stream ~2I~_~S ~I~_is not associated with a named file.~:>" #<SB-SYS:FD-STREAM for "socket 127.0.0.1:51620, peer: 127.0.0.1:43333" {1017CCA7E3}>)
  0: (ERROR USOCKET:TIMEOUT-ERROR :SOCKET NIL)
    1: (ERROR "~@<The stream ~2I~_~S ~I~_is not associated with a named file.~:>" #<SB-SYS:FD-STREAM for "socket 127.0.0.1:51620, peer: 127.0.0.1:43333" {1017CCA7E3}>)

this is from tracing error

[K1D77A]

After using the retry-request restart it works

[ajberkley]

It's maybe something wrong in the maze of auto-retry logic... but I can't see anything wrong. But, like I said, it's a maze.

[ajberkley]

Is this a "new" problem? (I mean, was it occuring before, but now with say the newest quicklisp it is?)

[K1D77A]

Nope its not a new problem. Last time I was working on this project I had this issue as well.

[ajberkley]

Unfortunately I don't have much of a lead. What it looks like is you should be seeing the "broken pipe error" which would make it clear what the problem is (in which case you as the caller have to decide what to do --- networking is notoriously unreliable and those who assume it is are always disappointed, so you'd be wise to use #'dex:retry-request-ntimes bound to an error handler.

What I'm confused about here is the odd error you are presented with in the debugger... I would assume it's something to do with us closing the stream in a handler-bind proactively without handling the error (which is probably a bad idea, and should be done in an unwind-protect clause instead...)

[K1D77A]

  0: (DEXADOR.BACKEND.USOCKET:REQUEST "http://127.0.0.1:43333/v1/service/!cs60byf9eysypieuud4ifecopzmym758bofp2ndicwagyzi63qsj6bc61my6d2g/new-payment" :METHOD :POST :CONTENT "{\"AMOUNT\":\"1000\"}" :HEADERS (("crc" . 3565213847) ("Authorization" . "Bearer apikey-ei2j55kipt3afmzyszrv19ezy1k1dd7d7l5grfvo8icugw652iwc60z534")))
    1: (DEXADOR.CONNECTION-CACHE::GET-FROM-LRU-POOL #<DEXADOR.CONNECTION-CACHE::LRU-POOL 3/8 elts
 https://api-m.sandbox.paypal.com: #<SSL-STREAM for #<FD-STREAM for "socket 192.168.0.178:59758, peer: 151.101.1.35:443" {1017ECF163}>>
 https://api.stripe.com: #<SSL-STREAM for #<FD-STREAM for "socket 192.168.0.178:59444, peer: 34.241.202.139:443" {1017ECF033}>>
 http://127.0.0.1:43333: #<FD-STREAM for "socket 127.0.0.1:38234, peer: 127.0.0.1:43333" {100EA18BD3}>> "http://127.0.0.1:43333")
    1: DEXADOR.CONNECTION-CACHE::GET-FROM-LRU-POOL returned
         #<SB-SYS:FD-STREAM for "socket 127.0.0.1:38234, peer: 127.0.0.1:43333" {100EA18BD3}>
    1: (ERROR SB-INT:BROKEN-PIPE :STREAM #<SB-SYS:FD-STREAM for "socket 127.0.0.1:38234, peer: 127.0.0.1:43333" {100EA18BD3}> :FORMAT-CONTROL "~@<~?~@[: ~2I~_~A~]~:>" :FORMAT-ARGUMENTS ("Couldn't write to ~S" (#<SB-SYS:FD-STREAM for "socket 127.0.0.1:38234, peer: 127.0.0.1:43333" {100EA18BD3}>) "Broken pipe"))
      2: (OPEN-STREAM-P #<SB-SYS:FD-STREAM for "socket 127.0.0.1:38234, peer: 127.0.0.1:43333" {100EA18BD3}>)
      2: OPEN-STREAM-P returned T
    1: (ERROR TYPE-ERROR :DATUM NIL :EXPECTED-TYPE SB-IMPL::BUFFER :CONTEXT NIL)
      2: (OPEN-STREAM-P #<SB-SYS:FD-STREAM for "socket 127.0.0.1:38234, peer: 127.0.0.1:43333" {100EA18BD3}>)
      2: OPEN-STREAM-P returned NIL
; Debugger entered on #<TYPE-ERROR expected-type: SB-IMPL::BUFFER datum: NIL>
  0: (ERROR USOCKET:TIMEOUT-ERROR :SOCKET NIL)

Idk if this is helpful at all, unfortunately #'request has most of its functionality internal through the use of labels so I am unable to trace the important parts to try and find the error :(

[ajberkley]

That's helpful. It says that the reason we get the bogus error message is because of something we are doing (maybe calling close-stream :abort t after the broken-pipe error is bad, for example?). Regardless, to handle these errors you should use the retry-n-times feature I pointed you at--- there's no great way to do anything reliably across a network except some sequence of retries and eventually giving up. We don't want to do that all internal to dexador, so we provide the retry function that you can put in a handler-bind around your calls. Tell me if that fixes things for you?

But, to be clear, the dexador bug is just in the type of error that ends up being thrown --- the underlying problem you should fix is that you aren't using any retry mechanism. I will try and fix our error handling so you get a more meaningful error message instead of an internal sbcl error.

[K1D77A]

Okay no problem. Thanks for the advice!

[ajberkley]

Actually I take it back... I'm not 100% sure this isn't a dexador problem. Anyhow, sorry for all the noise. I will look at it next weekend when I have some time.

[K1D77A]

No problem thanks :)