gopcua / opcua

Native Go OPC-UA library
MIT License
856 stars 259 forks source link

panic: close of closed channel #430

Closed salmanazmat666 closed 2 years ago

salmanazmat666 commented 3 years ago

I'm using multiple subscriptions under one client. In order to stop my code, I first cancel all the subscriptions using Subscription.Cancel(), then I do Client.Close(). I get following error,

panic: close of closed channel

goroutine 16 [running]:
github.com/gopcua/opcua/uasc.(*SecureChannel).Close.func1(0xc0035800e0)
        /home/salman/go/pkg/mod/github.com/gopcua/opcua@v0.2.0-rc2/uasc/secure_channel.go:838 +0x2f
github.com/gopcua/opcua/uasc.(*SecureChannel).Close(0xc0035800e0, 0xa95d00, 0xc0001120d0)
        /home/salman/go/pkg/mod/github.com/gopcua/opcua@v0.2.0-rc2/uasc/secure_channel.go:847 +0x1a5
github.com/gopcua/opcua.(*Client).monitor(0xc000bfc2a0, 0xa9ff40, 0xc002e25e00)
        /home/salman/go/pkg/mod/github.com/gopcua/opcua@v0.2.0-rc2/client.go:322 +0xfe6
created by github.com/gopcua/opcua.(*Client).Connect.func1
        /home/salman/go/pkg/mod/github.com/gopcua/opcua@v0.2.0-rc2/client.go:212 +0x65
mozesa commented 3 years ago

Dear @magiconair I would like to ask for your help again.

I have bumped into the same problem that is: panic: close of closed channel. Briefly, I connect to an OPC UA host, then subscribe a node, wait an update then unsubscribe and close the connection.

Here below is the mwe.

package opcua_test

import (
    "context"
    "fmt"
    "log"
    "testing"

    "github.com/gopcua/opcua"
    "github.com/gopcua/opcua/monitor"
    "github.com/gopcua/opcua/ua"
)

func TestOPCUA(t *testing.T) {
    t.Run(
        "Test", func(t *testing.T) {
            for i := 0; i < 100; i++ {
                Execute()
            }
        },
    )
}

func Execute() {
    ctx := context.Background()

    endpoints, err := opcua.GetEndpoints(ctx, "opc.tcp://localhost:4840")
    if err != nil {
        log.Println(err)
        return
    }

    ep := opcua.SelectEndpoint(endpoints, "None", ua.MessageSecurityModeFromString("None"))
    if ep == nil {
        log.Println("failed to find suitable endpoint")
        return
    }

    opts := []opcua.Option{
        opcua.SecurityPolicy("None"),
        opcua.SecurityModeString("None"),
        opcua.AuthAnonymous(),
        opcua.SecurityFromEndpoint(ep, ua.UserTokenTypeAnonymous),
    }
    client := opcua.NewClient(ep.EndpointURL, opts...)
    if err := client.Connect(ctx); err != nil {
        log.Println(err)
        return
    }
    defer func(client *opcua.Client) {
        err := client.Close()
        if err != nil {
            log.Println(err)
        }
    }(client)

    m, err := monitor.NewNodeMonitor(client)
    if err != nil {
        log.Println(err)
        return
    }

    ch := make(chan *monitor.DataChangeMessage, 32)

    nodes := []string{"ns=4;s=|var|CODESYS Control Win V3.Application.PLC_PRG.stJigBig.xTopRight"}

    sub, err := m.ChanSubscribe(ctx, &opcua.SubscriptionParameters{}, ch, nodes...)
    if err != nil {
        log.Println(err)
        return
    }
    defer func(sub *monitor.Subscription) {
        err := sub.Unsubscribe()
        if err != nil {
            log.Println(err)
        }
    }(sub)

    for {
        select {
        case node := <-ch:
            switch node.NodeID.String() {
            case nodes[0]:
                fmt.Println(node.Value.Value())
                return
            }
        }
    }
}
true
2021/09/03 14:02:15 EOF
true
2021/09/03 14:02:16  OK (0x0)
true
2021/09/03 14:02:16 EOF
true
2021/09/03 14:02:16 EOF
true
2021/09/03 14:02:16  OK (0x0)
true
2021/09/03 14:02:16 EOF
true
2021/09/03 14:02:29 EOF
true
2021/09/03 14:02:29  OK (0x0)
panic: close of closed channel

goroutine 914 [running]:
github.com/gopcua/opcua/uasc.(*SecureChannel).Close.func1()
    C:/Users/mozesa/go/pkg/mod/github.com/gopcua/opcua@v0.2.0-rc2/uasc/secure_channel.go:838 +0x26
github.com/gopcua/opcua/uasc.(*SecureChannel).Close(0xc00055b420)
    C:/Users/mozesa/go/pkg/mod/github.com/gopcua/opcua@v0.2.0-rc2/uasc/secure_channel.go:847 +0x194
github.com/gopcua/opcua.(*Client).monitor(0xc00055b340, {0xe0fe78, 0xc000091f40})
    C:/Users/mozesa/go/pkg/mod/github.com/gopcua/opcua@v0.2.0-rc2/client.go:322 +0xc38
created by github.com/gopcua/opcua.(*Client).Connect.func1
    C:/Users/mozesa/go/pkg/mod/github.com/gopcua/opcua@v0.2.0-rc2/client.go:212 +0x95

Process finished with the exit code 1
mozesa commented 3 years ago

Next run gives the below error.

true
2021/09/03 14:08:39  OK (0x0)
true
2021/09/03 14:08:40 EOF
true
2021/09/03 14:08:48  OK (0x0)
true
2021/09/03 14:08:48  OK (0x0)
2021/09/03 14:08:48 The server has reached its maximum number of sessions. StatusBadTooManySessions (0x80560000)
2021/09/03 14:08:48 The server has reached its maximum number of sessions. StatusBadTooManySessions (0x80560000)
2021/09/03 14:08:48 The server has reached its maximum number of sessions. StatusBadTooManySessions (0x80560000)
2021/09/03 14:08:48 The server has reached its maximum number of sessions. StatusBadTooManySessions (0x80560000)
2021/09/03 14:08:48 The server has reached its maximum number of sessions. StatusBadTooManySessions (0x80560000)
mozesa commented 3 years ago

Am I wrong or I overlook something important?

magiconair commented 3 years ago

This might get fixed by #462 . Can you try that patch?

mozesa commented 3 years ago

Thanks! Tomorrow, I will test it.

magiconair commented 3 years ago

problem is still there

12:00:09.862314 2.5: Stopped Node Monitorer with error context canceled. [2.10]
panic: close of closed channel
goroutine 222 [running]:
github.com/gopcua/opcua/uasc.(*SecureChannel).Close.func1()
    /Users/simo/go/pkg/mod/github.com/gopcua/opcua@v0.2.0-rc3/uasc/secure_channel.go:815 +0x25
github.com/gopcua/opcua/uasc.(*SecureChannel).Close(0xc00012e3c0)
    /Users/simo/go/pkg/mod/github.com/gopcua/opcua@v0.2.0-rc3/uasc/secure_channel.go:823 +0x188
github.com/gopcua/opcua.(*Client).monitor(0xc00037e680, {0x2a9d4b0, 0xc001a40200})
    /Users/simo/go/pkg/mod/github.com/gopcua/opcua@v0.2.0-rc3/client.go:303 +0xc2a
created by github.com/gopcua/opcua.(*Client).Connect.func1
    /Users/simo/go/pkg/mod/github.com/gopcua/opcua@v0.2.0-rc3/client.go:193 +0x95
magiconair commented 3 years ago

This means that the logic is trying to re-connect while shutting down the secure channel. We got this when we sent a CTRL-C to the client.

siscia commented 3 years ago

I found another instance of the problem.

We are reading nodes with types that we don't know how to deserialize, the reads returns an error and we decide to close the connection.

16:45:04.676307 New Pooled connection: 24 still 3 connection available.
16:45:04.875226 error: opcua: invalid extension object with id $something_we_dont_know
16:45:04.875614 Disconnected pooled connection: 24
panic: close of closed channel
goroutine 528 [running]:
github.com/gopcua/opcua/uasc.(*SecureChannel).Close.func1()
github.com/gopcua/opcua@v0.2.0-rc3/uasc/secure_channel.go:815 +0x25
github.com/gopcua/opcua/uasc.(*SecureChannel).Close(0xc0000ca780)
github.com/gopcua/opcua@v0.2.0-rc3/uasc/secure_channel.go:823 +0x188
github.com/gopcua/opcua.(*Client).monitor(0xc0004c0750, {0x1ea8bb0, 0xc0024fec00})
github.com/gopcua/opcua@v0.2.0-rc3/client.go:303 +0xc2a
created by github.com/gopcua/opcua.(*Client).Connect.func1
github.com/gopcua/opcua@v0.2.0-rc3/client.go:193 +0x95
mozesa commented 2 years ago

I have the same problem.

panic: close of closed channel

goroutine 36 [running]:
github.com/gopcua/opcua/uasc.(*SecureChannel).Close.func1()
    C:/Users/mozesa/go/pkg/mod/github.com/gopcua/opcua@v0.2.0/uasc/secure_channel.go:826 +0x25
github.com/gopcua/opcua/uasc.(*SecureChannel).Close(0xc000194180)
    C:/Users/mozesa/go/pkg/mod/github.com/gopcua/opcua@v0.2.0/uasc/secure_channel.go:834 +0x188
github.com/gopcua/opcua.(*Client).monitor(0xc0000b7450, {0x784ab8, 0xc0002000c0})
    C:/Users/mozesa/go/pkg/mod/github.com/gopcua/opcua@v0.2.0/client.go:303 +0xc2a
created by github.com/gopcua/opcua.(*Client).Connect.func1
    C:/Users/mozesa/go/pkg/mod/github.com/gopcua/opcua@v0.2.0/client.go:193 +0x95

I have it, when I call c.sub.Unsubscribe() together with c.opcua.Close(). Where c.opcua is *opcua.Client and c.sub is *monitor.Subscription. Should I have to only call c.opcua.Close()?!

I am using the latest v0.2.0 with go 1.17.3

magiconair commented 2 years ago

Ok. I'll look at this today

salmanazmat666 commented 2 years ago

Ok. I'll look at this today

@magiconair I think following might be helpful while you investigate this issue. I'm testing my code with -race flag, and I get multiple race conditions in the gopcua library. The logs for one related to SecureChannel are following. Apparently, client.sechan is being closed at multiple places concurrently, once inside client.Close() and then inside the client.monitor() at line 304 of v0.2.0.

WARNING: DATA RACE
Read at 0x00c0000a0360 by goroutine 7:
  github.com/gopcua/opcua.(*Client).Close()
      /home/salman/go/pkg/mod/github.com/gopcua/opcua@v0.2.0/client.go:492 +0xaa
  bitbucket.org/intechww/edge/cmd/deviceservices/kepware/driver.(*Driver).uaDisconnect()
      /home/salman/go/src/bitbucket.org/intechww/edge/cmd/deviceservices/kepware/driver/ua.go:137 +0xd0
  bitbucket.org/intechww/edge/cmd/deviceservices/kepware/driver.(*Driver).UADisconnect()
      /home/salman/go/src/bitbucket.org/intechww/edge/cmd/deviceservices/kepware/driver/ua.go:128 +0x7e
  bitbucket.org/intechww/edge/cmd/deviceservices/kepware/test.Test_UA()
      /home/salman/go/src/bitbucket.org/intechww/edge/cmd/deviceservices/kepware/test/ua_test.go:148 +0x1238
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1193 +0x202

Previous write at 0x00c0000a0360 by goroutine 23:
  github.com/gopcua/opcua.(*Client).monitor()
      /home/salman/go/pkg/mod/github.com/gopcua/opcua@v0.2.0/client.go:304 +0x14aa

Goroutine 7 (running) created at:
  testing.(*T).Run()
      /usr/local/go/src/testing/testing.go:1238 +0x5d7
  testing.runTests.func1()
      /usr/local/go/src/testing/testing.go:1511 +0xa6
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1193 +0x202
  testing.runTests()
      /usr/local/go/src/testing/testing.go:1509 +0x612
  testing.(*M).Run()
      /usr/local/go/src/testing/testing.go:1417 +0x3b3
  main.main()
      _testmain.go:91 +0x356

Goroutine 23 (running) created at:
  github.com/gopcua/opcua.(*Client).Connect.func1()
      /home/salman/go/pkg/mod/github.com/gopcua/opcua@v0.2.0/client.go:193 +0x7a
  sync.(*Once).doSlow()
      /usr/local/go/src/sync/once.go:68 +0x109
  sync.(*Once).Do()
      /usr/local/go/src/sync/once.go:59 +0x68
  github.com/gopcua/opcua.(*Client).Connect()
      /home/salman/go/pkg/mod/github.com/gopcua/opcua@v0.2.0/client.go:192 +0x2ac
  bitbucket.org/intechww/edge/cmd/deviceservices/kepware/driver.(*Driver).UAConnect()
      /home/salman/go/src/bitbucket.org/intechww/edge/cmd/deviceservices/kepware/driver/ua.go:102 +0x91d
  bitbucket.org/intechww/edge/cmd/deviceservices/kepware/test.Test_UA()
      /home/salman/go/src/bitbucket.org/intechww/edge/cmd/deviceservices/kepware/test/ua_test.go:65 +0x7e5
  testing.tRunner()
      /usr/local/go/src/testing/testing.go:1193 +0x202
magiconair commented 2 years ago

Hmm, I thought we caught them all but maybe not. Thank you.