Railway•3mo ago

HTTP logs for websockets

Great addition with the HTTP logs, this is very welcome, thanks for that! I have a graphql API with subscription, through websocket. - Is 0 an official websocket status, maybe the readyState property? or just a default value? - What does response time mean? the time since the connection is opened? I don't believe the subscriptions are responding in minutes in some cases.

11 Replies

Percy•3mo ago

Project ID: N/A

jeremyOP•3mo ago

N/A

Brody•3mo ago

- that's supposed to be an http code, but 0 is the default value for int lol, good catch - total round trip time id assume

jeremyOP•3mo ago

What "round trip time" would mean in a case of a subscription/websocket, the time of the first connection (where readyState went into OPEN) to the time the new message has been emitted, during the same connection? (I'm using this websocket library if that matters https://github.com/enisdenjo/graphql-ws) I'm just finding this a bit weird, regarding the queries/mutations response times from graphql, it looks to be on par with what I see in NewRelic, around ~250ms in average, which is what I see in the HTTP logs. Regarding the subscriptions it looks to be way slower that's what I get on NewRelic, average is around ~2ms, and in the HTTP logs, I'm seeing a lot of these responses time being over 100s

Brody•3mo ago

the time the client initializes a connection until the time the connection is closed, aka total duration

jeremyOP•3mo ago

okay I see, at least that makes sense why the duration is so long. It's honestly a bit confusing. I would expect when I see a log entry that it counts for non-connection emitted messages. I don't know if it's possible or not. I know NewRelic is integrated within my codebase, but their data makes more sense to me when I'm looking at the logs. Seeing a websocket that has a duration of 200s doesn't really help me to debug/investigate if there is an issue, just my 2cent

Brody•3mo ago

you can expand the log to see more information

jeremyOP•3mo ago

Yep I know, but that doesn't help much. When I see

Aug 26 13:15:27 GET /subscriptions 0 865.64s
method: "GET"
path: "/subscriptions"
host: REDACTED
httpStatus: 0
upstreamProto: "HTTP/1.1"
downstreamProto: "HTTP/1.1"
responseDetails: "connection was hijacked"
totalDuration: 865638
upstreamAddress: REDACTED
clientUa: REDACTED
upstreamRqDuration: 865638
txBytes: 0
rxBytes: 611
srcIp: REDACTED
edgeRegion: "unknown"

Aug 26 13:15:27 GET /subscriptions 0 865.64s
method: "GET"
path: "/subscriptions"
host: REDACTED
httpStatus: 0
upstreamProto: "HTTP/1.1"
downstreamProto: "HTTP/1.1"
responseDetails: "connection was hijacked"
totalDuration: 865638
upstreamAddress: REDACTED
clientUa: REDACTED
upstreamRqDuration: 865638
txBytes: 0
rxBytes: 611
srcIp: REDACTED
edgeRegion: "unknown"

that doesn't really help me in the context of a websocket or gives me additional information. It's mostly a feedback in this case, just giving you my thought

Brody•3mo ago

what would you like to see there?

Mig•3mo ago

hey, happy to improve this. The 0 status code and txBytes is because when the connection is upgraded to a websocket connection there is no longer a HTTP response hence the 0 status code. The txBytes (bytes sent to the client) also is part of the HTTP response so that's why it too is zero. It's common to perform a WS upgrade via an HTTP request so a 101 status code is expected. I can see if this is the behaviour we should implement.

jeremyOP•3mo ago

Maybe regarding httpStatus and txBytes, they could be hidden for websocket and/or have different color/label to differentiate http vs ws vs other protocols. Regarding the request duration, I would personally want to see a single emitted message duration. My service emitted this message to the client, it took 1ms. That would be more meaningful for me. And not based on the client initialization duration, but not sure if that's possible on your side

Gaming

Programming

HTTP logs for websockets