SubscriptionClient OnDisconnected() regression in v0.9.1

[amorey]

I have a subscription resolver that closes the connection server-side and when I upgraded to go-graphql-client v0.9.1 I noticed that the SubscriptionClient stopped calling the OnDisconnected() method on server-close. I'm attaching a test file that demonstrates this behavior (see below).

This is the log output in v0.9.0 ("OnDisconnected" present):

2023/03/07 12:43:10 {"type":"connection_init","payload":{"headers":{"foo":"bar"}}} client
2023/03/07 12:43:10 {"type":"connection_ack"} server
2023/03/07 12:43:10 {"id":"88b45ff2-b349-420c-866e-1a23d694649b","type":"start","payload":{"query":"subscription{helloGoodbye}"}} client
2023/03/07 12:43:10 OnConnected
2023/03/07 12:43:10 {"id":"88b45ff2-b349-420c-866e-1a23d694649b","type":"data","payload":{"data":{"helloGoodbye":"hello"}}} server
2023/03/07 12:43:10 {"id":"88b45ff2-b349-420c-866e-1a23d694649b","type":"data","payload":{"data":{"helloGoodbye":"goodbye"}}} server
2023/03/07 12:43:10 {"id":"88b45ff2-b349-420c-866e-1a23d694649b","type":"complete"} server
2023/03/07 12:43:10 {"id":"88b45ff2-b349-420c-866e-1a23d694649b","type":"stop"} client
2023/03/07 12:43:10 no running subscription. exiting... client
2023/03/07 12:43:11 http: Server closed
2023/03/07 12:43:11 OnDisconnected

And this is the log output in v0.9.1 ("OnDisconnected" missing):

2023/03/07 12:36:55 {"type":"connection_init","payload":{"headers":{"foo":"bar"}}} client
2023/03/07 12:36:55 {"type":"connection_ack"} server
2023/03/07 12:36:55 {"id":"33a56134-b9d4-4d1c-ac35-dc05fdbc4090","type":"start","payload":{"query":"subscription{helloGoodbye}"}} client
2023/03/07 12:36:55 OnConnected
2023/03/07 12:36:55 {"id":"33a56134-b9d4-4d1c-ac35-dc05fdbc4090","type":"data","payload":{"data":{"helloGoodbye":"hello"}}} server
2023/03/07 12:36:55 {"id":"33a56134-b9d4-4d1c-ac35-dc05fdbc4090","type":"data","payload":{"data":{"helloGoodbye":"goodbye"}}} server
2023/03/07 12:36:55 {"id":"33a56134-b9d4-4d1c-ac35-dc05fdbc4090","type":"complete"} server
2023/03/07 12:36:55 {"id":"33a56134-b9d4-4d1c-ac35-dc05fdbc4090","type":"stop"} client
2023/03/07 12:36:55 no running subscription. exiting... client
2023/03/07 12:36:56 http: Server closed

Is this behavior expected?

Here is the test file (will run in root directory of go-graphql-client):

package graphql

import (
    "context"
    "log"
    "net/http"
    "testing"
    "time"

    "github.com/graph-gophers/graphql-go"
    "github.com/graph-gophers/graphql-go/relay"
    "github.com/graph-gophers/graphql-transport-ws/graphqlws"
)

const sc_Schema = `
schema {
    subscription: Subscription
    query: Query
}

type Query {
}

type Subscription {
    helloGoodbye(): String!
}
`

type sc_Resolver struct{}

func (r *sc_Resolver) HelloGoodbye(ctx context.Context) <-chan string {
    c := make(chan string, 10)
    go func() {
        c <- "hello"
        c <- "goodbye"
        close(c)
    }()
    return c
}

func sc_setupServer() *http.Server {
    // init schema
    s, err := graphql.ParseSchema(sc_Schema, &sc_Resolver{})
    if err != nil {
        panic(err)
    }

    // graphql handler
    mux := http.NewServeMux()
    graphQLHandler := graphqlws.NewHandlerFunc(s, &relay.Handler{Schema: s})
    mux.HandleFunc("/graphql", graphQLHandler)
    server := &http.Server{Addr: ":8081", Handler: mux}

    return server
}

func TestSubscriptionClose(t *testing.T) {
    // init server
    server := sc_setupServer()
    go func() {
        if err := server.ListenAndServe(); err != nil {
            log.Println(err)
        }
    }()

    // init client
    client := NewSubscriptionClient("http://localhost:8081/graphql").
        WithConnectionParams(map[string]interface{}{
            "headers": map[string]string{
                "foo": "bar",
            },
        }).
        WithLog(log.Println).
        OnConnected(func() {
            log.Println("OnConnected")
        }).
        OnDisconnected(func() {
            log.Println("OnDisconnected")
        })

    // set up subscription
    var subscription struct {
        HelloGoodbye string
    }
    _, err := client.Subscribe(&subscription, nil, func(data []byte, e error) error {
        if e != nil {
            t.Fatal(e)
        }
        return e
    })
    if err != nil {
        t.Fatal(err)
    }

    // run client
    go func() {
        client.Run()
    }()
    defer client.Close()

    // stop test after 1 sec
    ctx, cancel := context.WithTimeout(context.Background(), 1*time.Second)
    defer server.Shutdown(ctx)
    defer cancel()
    <-ctx.Done()
}

[hgiasac]

Hi @amorey

Thanks for reporting. There would be some breaking changes after the update. I'll check soon

[hgiasac]

I have reproduced your issue. There are several points:

• The server doesn't send close events to the WebSocket client. The client doesn't know that the server was shut down and continues to receive messages and get timeout errors.
• Because the timeout of read requests is 1 minute, you can't get the error if you end the test case too early. You can set a lower timeout and log errors in the OnError event to know.

subscriptionClient = subscriptionClient.
    WithTimeout(5 * time.Second).
    OnError(func(sc *SubscriptionClient, err error) error {
        log.Println(err)
    })

I'll add an update to handle the timeout behavior of the WebSocket client soon.

[amorey]

@hgiasac Thanks for looking into the issue! I have a question about this line in the logs:

2023/03/07 12:43:10 {"id":"88b45ff2-b349-420c-866e-1a23d694649b","type":"complete"} server

Is this being received by the client? If so, how does the client respond? What happens to the underlying websocket connection?

[hgiasac]

According to the subscription spec, the message type notifies that the subscription operation was end. It is sent from the server. The WebSocket connection still continues to run if there is at least 1 other running subscription. If there isn't any subscription the client will automatically close.

[amorey]

Ahh I see, thanks for the explanation! Then it sounds like the issue I'm having is that I want to detect the end of the subscription but OnDisconnect() is called when the websocket connection is closed, not necessarily when the subscription is ended. Is there a way to detect the end of the subscription with go-graphql-client? If not, is this something you would consider adding to the client?

[hgiasac]

Yes, I'll improve this event Just to confirm. You expect the OnDisconnect event to be called whenever the WebSocket connection is disconnected, right? That makes sense because the event doesn't need to be triggered when the client is closed

[amorey]

That'd be great, thank you. In my specific use case, I'm using go-graphql-client in a unit test to ensure that the server is ending a subscription properly so I want to detect when the server emits a GQL_COMPLETE event.

[hgiasac]

Hi @amorey

Please check out the PR https://github.com/hasura/go-graphql-client/pull/82 to verify if it solves your issue, thanks

[amorey]

Works great! Thanks!