You signed in with another tab or window. Reload to refresh your session.You signed out in another tab or window. Reload to refresh your session.You switched accounts on another tab or window. Reload to refresh your session.Dismiss alert
Hi team, I think I may have found a bug with how we're awaiting the websocket connection. In the websocket transport's streamHandler method, it awaits the promise returned by establishWsConnection. This promise is resolved in the ws conn's open callback. In theory, this await should block until the connection is successfully established and the open callback is called. In practice, I believe Node is early exiting from the streamHandler async function and the background executor proceeds to its next iteration loop. See: nodejs/node#22088.
I discovered this after adding many logger statements in and around establishWsConnection to see what is happening and no log lines after establishWsConnection was being emitted, but there were no exceptions. Here is a snippet of those logs:
DEBUG [2023-01-25 23:54:25.172]: [] [WebSocketTransport] No established connection and new subscriptions available, connecting to WS
DEBUG [2023-01-25 23:54:25.172]: [] [WebSocketTransport] this.providerDataStreamEstablished=1674690865172
DEBUG [2023-01-25 23:54:25.172]: [] [WebSocketTransport] build conn handlers
DEBUG [2023-01-25 23:54:25.172]: [] [WebSocketTransport] wsConnection.readyState=0
DEBUG [2023-01-25 23:54:25.172]: [] [WebSocketTransport] added event listeners
DEBUG [2023-01-25 23:54:25.172]: [] [StreamingTransport] Setting local state to subscription set value
TRACE [2023-01-25 23:54:25.172]: [] [BackgroundExecutor] Finished background execute for endpoint "price", calling it again in 1ms...
These logs show that:
We set this.providerDataStreamEstablished right before the call to establishWsConnection.
Inside establishWsConnection's promise, we build the connection handlers, create the conn object (with an initial state of 0 i.e. connecting), and add the event listeners.
a. At this point we expect to block until the conn is created with a corresponding log from the open callback (Opened websocket connection. (event type ${event.type})) but no such log appears.
b. Additionally we would also expect log lines from streamHandler after establishWsConnection such as Sending subs/unsubs if there are any or Websocket handler complete, sleeping for but they also don't appear.
Instead the next log is from outside streamHandler, from the backgroundHandler function that calls streamHandler.
This issue blocks me from updating to any version that includes #16. That PR moves the sleep from the background executor to inside the transport. However, because of early exiting, we will never await the sleep at the end of the websocket transport's streamHandler and as a result the execution loop runs every 1ms. Additionally, this.connectionOpenedAt is never set properly so the next iteration will attempt to close the (not opened yet) connection causing more errors. It's possible this issue existed from the initial commit, but the fact that the bg executor slept for 5s somehow masked its effects.
Note: to be clear, I don't encounter this issue in integration tests because I assume the mock websocket conn & server is fast enough to not be a problem, but I do encounter this issue when running the EA connecting to the DP directly.
The text was updated successfully, but these errors were encountered:
Hi team, I think I may have found a bug with how we're awaiting the websocket connection. In the websocket transport's
streamHandler
method, it awaits the promise returned byestablishWsConnection
. This promise is resolved in the ws conn's open callback. In theory, this await should block until the connection is successfully established and the open callback is called. In practice, I believe Node is early exiting from the streamHandler async function and the background executor proceeds to its next iteration loop. See: nodejs/node#22088.I discovered this after adding many logger statements in and around establishWsConnection to see what is happening and no log lines after establishWsConnection was being emitted, but there were no exceptions. Here is a snippet of those logs:
These logs show that:
this.providerDataStreamEstablished
right before the call to establishWsConnection.Opened websocket connection. (event type ${event.type})
) but no such log appears.b. Additionally we would also expect log lines from streamHandler after establishWsConnection such as
Sending subs/unsubs if there are any
orWebsocket handler complete, sleeping for
but they also don't appear.backgroundHandler
function that calls streamHandler.This issue blocks me from updating to any version that includes #16. That PR moves the sleep from the background executor to inside the transport. However, because of early exiting, we will never await the sleep at the end of the websocket transport's streamHandler and as a result the execution loop runs every 1ms. Additionally,
this.connectionOpenedAt
is never set properly so the next iteration will attempt to close the (not opened yet) connection causing more errors. It's possible this issue existed from the initial commit, but the fact that the bg executor slept for 5s somehow masked its effects.Note: to be clear, I don't encounter this issue in integration tests because I assume the mock websocket conn & server is fast enough to not be a problem, but I do encounter this issue when running the EA connecting to the DP directly.
The text was updated successfully, but these errors were encountered: