search

andreykaipov / goobs

Go client library for OBS Studio
Apache License 2.0
137 stars 22 forks source link

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

Closed Gambloide closed 8 months ago

Gambloide commented 8 months ago

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

andreykaipov commented 8 months ago

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 https://github.com/andreykaipov/goobs/pull/80 that was intended to catch things like this, but I guess I forgot about the SendRequest function. PR https://github.com/andreykaipov/goobs/pull/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 commented 8 months ago

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 https://github.com/andreykaipov/goobs/pull/54#issuecomment-1794947130 👀:

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 commented 8 months ago

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!