Socketmode panic, write on closed channel

[krzysztofjopekacaisoft]

What happened

panic: send on closed channel

goroutine 47 [running]:
github.com/slack-go/slack/socketmode.(*Client).receiveMessagesInto(0x14000243950, {0x101c6e948, 0x1400043cac0}, 0x14000676c60, 0x1400061a6c0)
        /Users/censored/go/pkg/mod/github.com/slack-go/slack@v0.11.3/socketmode/socket_mode_managed_conn.go:484 +0x64c
github.com/slack-go/slack/socketmode.(*Client).runMessageReceiver(0x14000243950, {0x101c6e948, 0x1400043cac0}, 0x14000676c60, 0x1400061a6c0)
        /Users/censored/go/pkg/mod/github.com/slack-go/slack@v0.11.3/socketmode/socket_mode_managed_conn.go:363 +0x50
github.com/slack-go/slack/socketmode.(*Client).run.func4()
        /Users/censored/go/pkg/mod/github.com/slack-go/slack@v0.11.3/socketmode/socket_mode_managed_conn.go:133 +0x94
created by github.com/slack-go/slack/socketmode.(*Client).run
        /Users/censored/go/pkg/mod/github.com/slack-go/slack@v0.11.3/socketmode/socket_mode_managed_conn.go:128 +0x948
Exiting.

Looks like channel got closed:

slack/socketmode/socket_mode_managed_conn.go

Line 58 in 6f5eda2

defer close(messages)

before message got passed to the channel:

slack/socketmode/socket_mode_managed_conn.go

Line 485 in 6f5eda2

case sink <- event:

because we don't wait for completion:

slack/socketmode/socket_mode_managed_conn.go

Line 126 in 6f5eda2

// We don't wait on runMessageReceiver because it doesn't block on a select with the context,

Expected behavior

No panic

Steps to reproduce

Start socketmode slack client

reproducible code

https://github.com/slack-go/slack/blob/master/examples/socketmode/socketmode.go

Versions

• Go: 1.18
• slack-go/slack: 0.11.3

[tiantangkuohai]

I encounter the same problem 😔

[krzysztofjopekacaisoft]

@tiantangkuohai I think downgrade to 0.11.2 prevents the issue.

[kanata2]

Thanks for reporting. I'll confirm as soon as possible.

[kanata2]

Related: #1094

[kanata2]

I understand the problem. I'd like to think a bit about a solution.
If the problem is serious, please use v0.11.2.

[tiantangkuohai]

Thanks @krzysztofjopekacaisoft @kanata2 . I use v0.11.2, and it works for me.
I found that client needs to reconnect to Slack server continually from logs. But debug_info of Slack WebSocket message says approximate_connection_time is 18060 seconds.
"debug_info": { "host": "applink-6", "build_number": 20, "approximate_connection_time": 18060 },

Reconnect logs:
socketmode: 2022/11/09 20:46:44 socket_mode_managed_conn.go:167: Reconnecting due to websocket: close 1006 (abnormal closure): unexpected EOF socketmode: 2022/11/09 21:28:18 socket_mode_managed_conn.go:167: Reconnecting due to ping timeout: Slack did not send us WebSocket PING for more than Client.maxInterval socketmode: 2022/11/09 21:30:43 socket_mode_managed_conn.go:167: Reconnecting due to websocket: close 1006 (abnormal closure): unexpected EOF socketmode: 2022/11/09 21:55:46 socket_mode_managed_conn.go:167: Reconnecting due to websocket: close 1006 (abnormal closure): unexpected EOF socketmode: 2022/11/09 22:22:03 socket_mode_managed_conn.go:167: Reconnecting due to websocket: close 1006 (abnormal closure): unexpected EOF socketmode: 2022/11/09 22:36:36 socket_mode_managed_conn.go:167: Reconnecting due to websocket: close 1006 (abnormal closure): unexpected EOF socketmode: 2022/11/09 22:42:32 socket_mode_managed_conn.go:167: Reconnecting due to websocket: close 1006 (abnormal closure): unexpected EOF socketmode: 2022/11/09 23:10:13 socket_mode_managed_conn.go:167: Reconnecting due to websocket: close 1006 (abnormal closure): unexpected EOF socketmode: 2022/11/09 23:28:23 socket_mode_managed_conn.go:167: Reconnecting due to ping timeout: Slack did not send us WebSocket PING for more than Client.maxInterval socketmode: 2022/11/09 23:30:28 socket_mode_managed_conn.go:167: Reconnecting due to websocket: close 1006 (abnormal closure): unexpected EOF socketmode: 2022/11/09 23:57:20 socket_mode_managed_conn.go:167: Reconnecting due to ping timeout: Slack did not send us WebSocket PING for more than Client.maxInterval socketmode: 2022/11/10 00:10:58 socket_mode_managed_conn.go:167: Reconnecting due to websocket: close 1006 (abnormal closure): unexpected EOF socketmode: 2022/11/10 00:51:08 socket_mode_managed_conn.go:167: Reconnecting due to websocket: close 1006 (abnormal closure): unexpected EOF socketmode: 2022/11/10 01:14:14 socket_mode_managed_conn.go:167: Reconnecting due to websocket: close 1006 (abnormal closure): unexpected EOF

I creates Client with below options
socketmode.OptionDebug(true), socketmode.OptionPingInterval(60*time.Second), socketmode.OptionLog(log.New(os.Stdout, "socketmode: ", log.Lshortfile|log.LstdFlags)
if I don't set OptionPingInterval, ping timeout happens every a few minutes.

[lololozhkin]

Facing the same issue :(. I think awaiting of this goroutine will solve the problem)

Yes, we need to wait for reading json from websocket, that can be too slow, but we can also run reading json asyncroniously and watch on ctx.Done() in select. I could implement it in PR, can you give me some feedback?

now it is written in socket_mode_managed_conn.go:442

event := json.RawMessage{}
err := conn.ReadJSON(&event)

But it could be something like that

event := json.RawMessage{}

readJsonErr := make(chan error)
go func() {
    readJsonErr <- conn.ReadJSON(&event)
}()

select {
case <-ctx.Done():
    err = conn.Close() // we need to close connection to websocket
    if err != nil {
    // ....
    }
    return ctx.Error()
case err <- readJsonErr:
    // future error handling
}

What do you think?
In this case we could cancel awaiting of json read and wait for goroutine in main cycle.

[lololozhkin]

Created PR to resolve this problem, waiting for review and merging.

[kanata2]

Thanks! I'll review later.