Goobs panics when trying to send a request after OBS has been closed

[Gambloide]

Hey! It's me again.
Last time goobs was crashing OBS, now I found out how to crash goobs with OBS. 😅
All it takes is to close OBS:

Issue
Goobs panics following these steps:

1. create a new client (and connection) with goobs.New
2. close OBS
3. try to send a request

Expected Result
An error is returned by goobs to be handled by the application.

Actual result
Goobs panics:

panic: send on closed channel

goroutine 40 [running]:
github.com/andreykaipov/goobs/api.(*Client).SendRequest(0xc0001829f0, {0xdd0580, 0x1016020}, {0xdd0f70, 0xc00019e780})
	C:/Users/gambloide/go/pkg/mod/github.com/andreykaipov/goobs@v1.2.2/api/client.go:78 +0x2b2

Panicking code:

c.Opcodes <- &opcodes.Request{
    Type: name,
    ID:   id,
    Data: requestBody,
}

Code to reproduce the panic

package main

import (
    "errors"
    "fmt"
    "log"
    "time"

    "github.com/andreykaipov/goobs"
)

const serverPort = <yourport>
const serverPassword = <yourpassword>

func main() {
    var client *goobs.Client
    var err error
    const reconnectDelay = 5

    host := fmt.Sprintf("localhost:%d", serverPort)

    // wait for OBS Websocket Server to be connectable, then connect
    for {
    	client, err = goobs.New(host, goobs.WithPassword(serverPassword))
    	if err == nil {
            log.Println("Connected to OBS Websocket Server: " + host)
            break
    	}

    	log.Println("Failed to connect to OBS: ", err)
    	log.Printf("Will try to connect to OBS again in %d seconds\n", reconnectDelay)
    	time.Sleep(reconnectDelay * time.Second)
    }

    // keep sending requests
    // expected: if the client disconnects or can't connect an error is returned
    // actual: instead, goobs panics because it tries to send on the closed c.Opcodes channel 
    for {
        _, err := client.Stream.GetStreamStatus()
        if err != nil {
            break
        }
        time.Sleep(time.Second)
    }
}

Notes

• I looked through the closed issues and came across this Handling reconnects #48, but the code given there does not detect OBS being closed. As far as I am aware, there is no way to assert if the client is in a usable state for someone using goobs.
• I tried to adjust the SendRequest function to prevent or recover from the panic, but my understanding of the internal of goobs and my general experience with go were not sufficient to identify a simple fix inside the method itself. But since something is closing/releasing the Opcodes channel, the same something might be able to e.g. set a flag indicating the client to be in an unusable state, causing SendRequest to return an error instead of trying to send down a closed channel?
• Operating system: Microsoft Windows 10 Pro Version - 10.0.19045 Build 19045
• Go version: 1.22.0
• goobs version: v1.2.2
• OBS version: 30.0.2 (64bit)
• OBS Websocket Version: 5.3.4

[andreykaipov]

Hello! I was able to reproduce it.

But since something is closing/releasing the Opcodes channel, the same something might be able to e.g. set a flag indicating the client to be in an unusable state, causing SendRequest to return an error instead of trying to send down a closed channel?

You have the right idea. I added a disconnected flag in #80 that was intended to catch things like this, but I guess I forgot about the SendRequest function. PR #142 should fix this.

---

Interestingly when I ran your example sometimes I got a clean exit from the request, and sometimes I got the panic. When running with GOOBS_LOG=trace:

19:18:34 client.go:326: [TRACE] Got ExitStarted event:
19:18:35 client.go:73: [TRACE] Sending GetStreamStatus Request with ID bd603d15-3cfe-4e78-6e41-6d608d1a3807
19:18:35 client.go:342: [TRACE] Got GetStreamStatus Request with ID bd603d15-3cfe-4e78-6e41-6d608d1a3807
19:18:35 client.go:260: [TRACE] Raw server message: {"d":{"requestId":"bd603d15-3cfe-4e78-6e41-6d608d1a3807","requestStatus":{"code":207,"comment":"OBS is not ready to perform the request.","result":false},"requestType":"GetStreamStatus"},"op":7}
19:18:35 client.go:350: [TRACE] Got GetStreamStatus Response for ID bd603d15-3cfe-4e78-6e41-6d608d1a3807 (207)
2024/03/03 19:18:35 Error:  request GetStreamStatus: NotReady (207): OBS is not ready to perform the request.

Here what seems to happen is the client got an ExitStarted event, but for whatever reason the server didn't shut down fully yet. So the client was still able to send another request after ExitStarted, but because the server was in the process of shutting down, it was still able to send a response of NotReady.

And here it is when it panics:

19:17:49 client.go:326: [TRACE] Got ExitStarted event:
19:17:49 client.go:240: [DEBUG] Connection terminated: websocket: close 1001 (going away): Server stopping.
19:17:49 client.go:130: [TRACE] Closing internal channels
19:17:49 client.go:242: [TRACE] Finished handling raw server messages
19:17:49 client.go:358: [TRACE] Finished handling opcodes
19:17:50 client.go:73: [TRACE] Sending GetStreamStatus Request with ID 1721f7f3-ad9e-44e7-4ae5-1bf764101f3c
panic: send on closed channel

goroutine 1 [running]:
github.com/andreykaipov/goobs/api.(*Client).SendRequest(0xc00007eab0, {0x747140?, 0x92ae00}, {0x747ba8, 0xc00002c6c0})
        /home/andrey/gh/goobs/api/client.go:78 +0x2d4
github.com/andreykaipov/goobs/api/requests/stream.(*Client).GetStreamStatus(0xc000052178, {0x0?, 0xc000137e50?, 0xc00016dee0?})
        /home/andrey/gh/goobs/api/requests/stream/xx_generated.getstreamstatus.go:49 +0x89
main.main()
        /home/andrey/gh/goobs/_examples/basic/main.go:41 +0x345
exit status 2

Now here it's interesting because the client gets the ExitStarted event and I guess the server got further in the shutting down process because we got that Connection terminated: websocket: close 1001 line. And then it closes the channels but still sends the message.

After the fix it doesn't panic anymore:

19:32:22 client.go:325: [TRACE] Got ExitStarted event:
19:32:23 client.go:239: [DEBUG] Connection terminated: websocket: close 1001 (going away): Server stopping.
19:32:23 client.go:129: [TRACE] Closing internal channels
19:32:23 client.go:241: [TRACE] Finished handling raw server messages
19:32:23 client.go:357: [TRACE] Finished handling opcodes
19:32:23 client.go:75: [TRACE] Sending GetStreamStatus Request with ID 09c4c30b-eb14-4f9c-5b64-6442c5ce177f
2024/03/03 19:32:23 Error:  request GetStreamStatus: client already disconnected

[andreykaipov]

I published a new release with the fix v1.2.3. Please lemme know if it works for you! And thank you for reporting this!

I think this comment foreshadowed this issue #54 (comment) 👀:

There's no locking during authentication (creating the OBS client), and there's no locking during the client's closure. Therefore, you should ensure that no goroutines are sending OBS messages during authentication, and similarly, you should ensure that no goroutines are still sending messages when the OBS client is closing. Otherwise, you might still encounter that error message.

[Gambloide]

v1.2.3 seems to fix the panic!

I have tried it 5 times now and instead of a panic get an error returned: 2024/03/04 17:20:38 request GetStreamStatus: client already disconnected

Very nice!