Clojurians Log v2

I am on 0.6.4

I can try to make a repro, @kingmob might already have a part of the code base that contain the code.

It’s a POST request that is quite normal except for the part that it gets SSE in return (OpenAI API)

So I think it might have something to do with SSE handling

That's the pseudo-request Aleph uses to close a connection. Since a connection is really just request->response fn, Zach decided to close them by sending a sentinel request. When you call close-connection, it sends that request, and certain code looks for :aleph/close true . The "invalid" part is just because the RFCs promise it will never be a valid TLD

But it closes prematurely, before receiving any SSE

The only difference between working and non working calls is updating to 0.7

Hmmm. Are you still on HTTP/1 or did you add ALPN and HTTP/2 to the mix?

I changed nothing but the aleph version, I assume it’s on http1 then?

Should still be on HTTP/1 then, but some of that code was refactored. I'm not sure how much changed on the client-side between 0.6.3/0.6.4 and 0.7.0. It's been mostly server stuff in recent months.

Quick check: do you have an http-versions key somewhere? If not, you're on HTTP/1 still

2024-01-17 17:04:29.191 [staging_02] [DEBUG] aleph.http.client Using HTTP protocol: http/1.1 {:authority http://brian-gpt4-france.openai.azure.com, :ssl? true, :force-h2c? false}

I assume you're not using a custom pool-builder-fn

yeah I'm not

here's the logs for a request 0.7:

2024-01-17 17:04:29.192 [staging_02] [DEBUG] aleph.http.client http1 client pipeline DefaultChannelPipeline
	Handlers:
		activity-logger: LoggingHandler (#624743621)
		ssl-handler: SslHandler (#607389596)
		pause-handler: netty$pause_handler$reify__38645 (#1503766034)
		http-client: HttpClientCodec (#1894974881)
		streamer: ChunkedWriteHandler (#1366243763)
		handler: client$http1_client_handler$reify__39781 (#178696404)
		debug: common$add_non_http_handlers$reify__38868 (#1233115065)


2024-01-17 17:04:29.193 [staging_02] [DEBUG] aleph.http.client Unpausing pipeline
2024-01-17 17:04:29.195 [staging_02] [DEBUG] aleph.http.client client request: {:path "//openai/deployments/brian-gpt4-turbo/chat/completions", :user-info nil, :request-url "", :headers {"api-key" "redacted", "content-type" "application/json"}, :server-port nil, :content-type "application/json", :uri "//openai/deployments/brian-gpt4-turbo/chat/completions", :server-name "", :query-string "api-version=2023-05-15", :body "redacted", :scheme :https, :request-method :post}
2024-01-17 17:04:29.197 [staging_02] [DEBUG] aleph.netty pause-handler - firing buffered msgs
2024-01-17 17:04:29.197 [staging_02] [DEBUG] aleph.http.core send-contiguous-body headers: #object[io.netty.handler.codec.http.DefaultHttpHeaders 0x314a922f DefaultHttpHeaders[Api-Key: redacted, Content-Type: application/json, host: ]]
2024-01-17 17:04:29.199 [staging_02] [DEBUG] aleph.http.client client request: {:aleph/close true, :path "/", :user-info nil, :request-url "", :server-port nil, :uri "/", :server-name "closing.aleph.invalid", :query-string nil, :scheme :http, :request-method :get}
2024-01-17 17:04:29.200 [staging_02] [DEBUG] aleph.http.client responses stream closed.

I don't have the equivalent for 0.6.4 because it isn't logging anything it just works silently 😅

close-connection is called by the Dirigiste object pool when it destroys the connection. Sometimes this indicates an error, but there are none in the logs, and there are normal circumstances that would cause a connection to be closed

I'm looking...

The code was renamed and commented a bit for clarity, but the normal closing code seems the same as in 0.6.4. Basically, if you get responses out of order, or the server fails to close the chunked stream it's sending, Aleph will detect this (a violation in HTTP/1) and signal the connection for closing

but it works everytime with 0.6.4 and it fails everytime with 0.7

I believe you, I'm just verbalizing the possibilities as part of my thought process

Do you see http1-req-handler - response: in your logs anywhere nearby?

Dumb question, but you're not changing keep-alive? to false anywhere, are you?

Also, do you see connection was closed after anywhere nearby in the logs?

And you're not seeing any timeouts?

One thing to try would be to turn on TRACE-level logging for Aleph. Most of the exit points will indicate why the connection is being closed at trace-level

See any received msg of class?

Ok so I tried to repro in the codebase you worked on and it doesn't fail there, but running the same test in the broader codebase does fail

Yeah, I was testing it on the brain-ai repo and... "It Works On My Machine.™️"

I'm actually kind of surprised, I would have expected to see more log statements if debugging was turned on

Maybe try (log/set-min-level! :trace) from the REPL?

Like, there's nothing about response bodies, in the log snippet you sent, which seems sus

It sends the request out and 2ms later, the connection is being closed with nothing in-between, where I'd expect a bunch of stuff.

2024-01-18T09:49:27.803Z project2501 TRACE [aleph.http.client:?] - http1-req-handler fired
2024-01-18T09:49:27.803Z project2501 DEBUG [aleph.http.core:?] - send-contiguous-body headers: #object[io.netty.handler.codec.http.DefaultHttpHeaders 0x57eab7a0 DefaultHttpHeaders[Api-Key: , Content-Type: application/json, host: ]]
2024-01-18T09:49:27.805Z project2501 TRACE [aleph.http:?] - Request failed. Disposing of connection...
2024-01-18T09:49:27.806Z project2501 TRACE [aleph.http.client:?] - http-req-fn fired

Hmm, that means an Exception was placed in the deferred instead of a valid Ring response. It should return the exception in an error-deferred

one thing that is complicating the debugging is that the logging is failing because: "Execution error (IllegalArgumentException) at aleph.http.client/http1-req-handler$fn (client.clj:556). Multiple methods in multimethod 'print-method' match dispatch value: class manifold.deferred.Deferred -> interface java.util.concurrent.CompletionStage and interface manifold.deferred.IDeferred, and neither is preferred"

Huh, that's new

its from (log/debug "http1-req-handler - response: " resp)

Is promesa in your deps?

Manifold deferreds implement CompletionStage as of 0.4.x, but CompletionStage isn't a type used for print-method. Promesa adds that, though

Try (prefer-method print-method IDeferred CompletionStage)

yes looks like promesa is in the deps tree

coming from transit and http-kit as transitive deps

Does the prefer-method call fix that?

I have to figure how to call it it says unable to resolve symbol IDeferred

Try it from the manifold.deferred ns?

That's where IDeferred is defined anyway

yeah it fixed everything

looks like that was the whole issue, this added debug statement was triggering the exception

Wait, it fixed everything? Or it just fixed your ability to see the errors you're interested in? 😄

looks like the error was what was interrupting the connection so yes everything

Heh. OK, we'll cut a release updating Manifold and Aleph.

thanks for the help!

No prob

Hello Eric! Did you bump straight from Aleph 0.6.0 to 0.7.0 or were you using version 0.6.3? Can you share with us the code? Version 0.6.2 made the client more restrictive in terms of what it accepts [1], that might be it. But I don't think so regarding your error message. [1] : https://github.com/clj-commons/aleph/pull/685