Stuck in infinite loop of StatusBadNoSubscription (0x80790000)

[salmanazmat666]

Hi,
When I cancel a subscription, without closing the client connection, sometimes the code gets stuck in a loop trying to create secure channel indefinitely.

Following is the code I'm using that can reproduce the issue. It doesn't happen always so to reproduce you might have to run it a couple of times.

I have attached the log files with debugging enabled, for when the code works fine (logs_ok.txt) and when it doesn't (logs_not_ok.txt).

package main
import (
	"context"
	"flag"
	"fmt"
	"log"
	"time"

	"github.com/gopcua/opcua"
	"github.com/gopcua/opcua/debug"
	"github.com/gopcua/opcua/ua"
)
func main() {
	var (
		endpoint = flag.String("endpoint", "opc.tcp://192.168.189.1:49320", "OPC UA Endpoint URL")
		policy   = flag.String("policy", "None", "Security policy: None, Basic128Rsa15, Basic256, Basic256Sha256. Default: None")
		mode     = flag.String("mode", "None", "Security mode: None, Sign, SignAndEncrypt. Default: None")
		certFile = flag.String("cert", "", "Path to cert.pem. Required for security mode/policy != None")
		keyFile  = flag.String("key", "", "Path to private key.pem. Required for security mode/policy != None")
		nodeID   = flag.String("node", "ns=2;s=HONDA.DEV1.T1", "node id to subscribe to")
		interval = flag.String("interval", opcua.DefaultSubscriptionInterval.String(), "subscription interval")
	)
	flag.BoolVar(&debug.Enable, "debug", true, "enable debug logging")
	flag.Parse()
	log.SetFlags(0)

	subInterval, err := time.ParseDuration(*interval)
	if err != nil {
		log.Fatal(err)
	}

	// add an arbitrary timeout to demonstrate how to stop a subscription
	// with a context.
	ctx, cancel := context.WithCancel(context.Background())
	defer cancel()

	endpoints, err := opcua.GetEndpoints(ctx, *endpoint)
	if err != nil {
		log.Fatal(err)
	}
	ep := opcua.SelectEndpoint(endpoints, *policy, ua.MessageSecurityModeFromString(*mode))
	if ep == nil {
		log.Fatal("Failed to find suitable endpoint")
	}

	fmt.Println("*", ep.SecurityPolicyURI, ep.SecurityMode)

	opts := []opcua.Option{
		opcua.SecurityPolicy(*policy),
		opcua.SecurityModeString(*mode),
		opcua.CertificateFile(*certFile),
		opcua.PrivateKeyFile(*keyFile),
		opcua.AuthAnonymous(),
		opcua.SecurityFromEndpoint(ep, ua.UserTokenTypeAnonymous),
	}

	c := opcua.NewClient(ep.EndpointURL, opts...)
	if err := c.Connect(ctx); err != nil {
		log.Fatal(err)
	}
	defer c.Close()

	notifyCh := make(chan *opcua.PublishNotificationData)

	sub, err := c.Subscribe(&opcua.SubscriptionParameters{
		Interval: subInterval,
	}, notifyCh)
	if err != nil {
		log.Fatal(err)
	}
	log.Printf("Created subscription with id %v", sub.SubscriptionID)

	id, err := ua.ParseNodeID(*nodeID)
	if err != nil {
		log.Fatal(err)
	}

	miCreateRequest := opcua.NewMonitoredItemCreateRequestWithDefaults(id, ua.AttributeIDValue, uint32(42))

	res, err := sub.Monitor(ua.TimestampsToReturnBoth, miCreateRequest)
	if err != nil || res.Results[0].StatusCode != ua.StatusOK {
		log.Fatal(err)
	}

	stop := make(chan int)
	time.AfterFunc(5*time.Second, func(){
		stop <- 0
	})

	breakLoop := false
	for {
		if breakLoop {
			break
		}
	
		select {
		case <-stop:
			sub.Cancel()
			breakLoop = true
		case res := <-notifyCh:
			if res.Error != nil {
				log.Print(res.Error)
				continue
			}

			switch x := res.Value.(type) {
			case *ua.DataChangeNotification:
				for _, item := range x.MonitoredItems {
					data := item.Value.Value.Value()
					log.Printf("MonitoredItem with client handle %v = %v", item.ClientHandle, data)
				}

			case *ua.EventNotificationList:
				fmt.Println("Got an event, why ?")
			default:
				log.Printf("what's this publish result? %T", res.Value)
			}
		}
	}

// doing some tasks here
	time.Sleep(2*time.Second)
}

[salmanazmat666]

It seems like if a publish response is pending and all the subscriptions are cancelled, the server doesn't send publish response that the client was expecting. And, upon creating the new secure channel and then session, the client sends the pending publish request again, even though new requests are not being sent since the publishing loop is paused, as a response to this publish request the server returns NoSubscription error and this continues forever. This also explains why this issue doesn't come up every time, since if the subscriptions are cancelled when no publish response is pending, things go smoothly.

[diericd]

I bumped into this issue too. This seems to be an error in the auto-reconnect logic. In my humble opinion the getting a ua.StatusBadNoSubscription from the server should not trigger the whole reconnection logic. Also if it is triggered the reconnection logic always try to resume the subscription (even if there where non to start with) which fails and restarts until all server session/connection are depleted.

I made it work by ignoring the ua.StatusBadNoSubscription in the autoreconnect monitor but the way I did it does not seem ideal.

client.go:

			dlog.Print("auto-reconnecting")
			switch err {
			case io.EOF:
				// the connection has been closed
				action = createSecureChannel

			case syscall.ECONNREFUSED:
				// the connection has been refused by the server
				action = abortReconnect

			case ua.StatusBadNoSubscription:
				action = ignoreError

			default:
				switch x := err.(type) {
				case *uacp.Error:
					switch ua.StatusCode(x.ErrorCode) {
					case ua.StatusBadSecureChannelIDInvalid:
						// the secure channel has been rejected by the server
						action = createSecureChannel
					case ua.StatusBadNoSubscription:
						action = none
						c.state.Store(Connected)

					case ua.StatusBadSessionIDInvalid:
						// the session has been rejected by the server
						action = recreateSession

					case ua.StatusBadSubscriptionIDInvalid:
						// the subscription has been rejected by the server
						action = transferSubscriptions

					case ua.StatusBadCertificateInvalid:
						// todo(unknownet): recreate server certificate
						fallthrough

					default:
						// unknown error has occured
						action = createSecureChannel
					}

				default:
					// unknown error has occured
					dlog.Printf("error %+v", x)
					action = createSecureChannel
				}
			}

			c.state.Store(Disconnected)

			c.pauseSubscriptions()

			var (
				subsToRepublish []uint32 // subscription ids for which to send republish requests
				subsToRecreate  []uint32 // subscription ids which need to be recreated as new subscriptions
				availableSeqs   map[uint32][]uint32
			)

			for action != none {

				select {
				case <-ctx.Done():
					return

				default:
					switch action {

					case ignoreError:
						c.state.Store(Connected)
						action = none
...

[cailloumajor]

I also ran into this issue. I found a workaround:

• creating a dummy subscription, right after connecting the client
• starting a goroutine constantly pulling and dropping elements on the notification channel

[magiconair]

I'll try to have a look

[salmanazmat666]

I also ran into this issue. I found a workaround:

* creating a dummy subscription, right after connecting the client

* starting a goroutine constantly pulling and dropping elements on the notification channel

[danielcb]

Any updates on this? Currently all subscriptions end in an endless recreate loop with StatusBadSessionIDInvalid, when the connection between client and server are interrupted.