StatusBadSessionNotActivated in updateNamespaces call during recreateSession action while reconnecting

[law-dwg]

We are experiencing an issue with the autoreconnect functionality when trying to reestablish a connection to an OPC UA server that has been reset. In my current working example, I have a test server running out of a docker container, in which an initial connection can be established, but is unable to be reestablished when the container is restarted (docker pause seems to work fine, which makes sense since the connection is still active, just frozen)

Here is my small example:

package main

import (
	"context"
	"log"
	"time"

	"github.com/gopcua/opcua"
	"github.com/gopcua/opcua/debug"
	"golang.org/x/exp/slog"
)

func main() {
	debug.Enable = true
	log.SetFlags(log.LstdFlags | log.Lshortfile)
	endpoint := "opc.tcp://localhost:4840"
	ctx := context.Background()
	c := opcua.NewClient(endpoint, opcua.AutoReconnect(true))

	if err := c.Connect(ctx); err != nil {
		log.Fatal(err)
	}
	defer c.Close(ctx)

	t := time.NewTicker(1 * time.Second)
	stop := time.After(60 * time.Second)

loop:
	for {
		select {
		case v := <-t.C:
			slog.Info("TICK", "v", v)
			slog.Info(c.State().String())

		case <-stop:
			break loop
		}
	}
	slog.Info("TICKS ARE DONE", "STATE", c.State().String())
}

---

Steps to reproduce are:

1. start a docker container in the background with opcua server forwarding port 4840:

docker run -p 4840:4840 opcuadummyserver:v0.0.1

2. run above code

go run main.go

3. kill container
4. run step 1 again
5. observe main.go logs

steps 2-4 should be completed within 60 seconds otherwise the stop duration should be changed.

---

The debug logs from the package seem to indicate that its stuck in a loop delivering the following messages repeatedly:

debug: client: monitor: action: createSecureChannel
debug: uacp 10858: close
debug: uasc 10858: readChunk EOF
debug: uasc 10858: Close()
debug: client: monitor: trying to recreate secure channel
debug: uacp: connecting to opc.tcp://localhost:4840
debug: uacp 10859: start HEL/ACK handshake
debug: uacp 10859: sent HELF with 56 bytes
debug: uacp 10859: recv ACKF with 28 bytes
debug: uacp 10859: recv &uacp.Acknowledge{Version:0x0, ReceiveBufSize:0xffff, SendBufSize:0xffff, MaxMessageSize:0x6400000, MaxChunkCount:0x641}
debug: uasc 10859/1: send *ua.OpenSecureChannelRequest with 132 bytes
debug: uacp 10859: recv OPNF with 135 bytes
debug: uasc 10859/1: recv OPNF with 135 bytes
debug: uasc 10859/1: recv *ua.OpenSecureChannelResponse
debug: uasc 10859/1: sending *ua.OpenSecureChannelResponse to handler
debug: uasc 10859: received security token. channelID=10401 tokenID=13 createdAt=2023-08-17T12:53:59Z lifetime=1h0m0s
debug: client: monitor: secure channel recreated

debug: client: monitor: action: restoreSession
debug: client: monitor: trying to restore session
debug: uasc 10859: security token is refreshed at 2023-08-17T13:38:59Z (45m0s). channelID=10401 tokenID=13
debug: uasc 10859: security token expires at 2023-08-17T14:08:59Z. channelID=10401 tokenID=13
debug: uasc 10859/2: send *ua.ActivateSessionRequest with 114 bytes
debug: uacp 10859: recv MSGF with 52 bytes
debug: uasc 10859/2: recv MSGF with 52 bytes
debug: uasc 10859/2: err: The session id is not valid. StatusBadSessionIDInvalid (0x80250000)
debug: uasc 10859/2: sending *ua.ServiceFault to handler
debug: client: monitor: restore session failed: The session id is not valid. StatusBadSessionIDInvalid (0x80250000)

debug: client: monitor: action: recreateSession
debug: client: monitor: trying to recreate session
debug: uasc 10859/3: send *ua.CreateSessionRequest with 245 bytes
debug: uacp 10859: recv MSGF with 572 bytes
debug: uasc 10859/3: recv MSGF with 572 bytes
debug: uasc 10859/3: recv *ua.CreateSessionResponse
debug: uasc 10859/3: sending *ua.CreateSessionResponse to handler
debug: uasc 10859/4: send *ua.ActivateSessionRequest with 114 bytes
debug: uacp 10859: recv MSGF with 96 bytes
debug: uasc 10859/4: recv MSGF with 96 bytes
debug: uasc 10859/4: recv *ua.ActivateSessionResponse
debug: uasc 10859/4: sending *ua.ActivateSessionResponse to handler
debug: uasc 10859/5: send *ua.CloseSessionRequest with 60 bytes
debug: uacp 10859: recv MSGF with 52 bytes
debug: uasc 10859/5: recv MSGF with 52 bytes
debug: uasc 10859/5: recv *ua.CloseSessionResponse
debug: uasc 10859/5: sending *ua.CloseSessionResponse to handler
debug: client: monitor: session recreated

debug: client: monitor: trying to update namespaces
debug: uasc 10859/6: send *ua.ReadRequest with 96 bytes
debug: uacp 10859: recv MSGF with 52 bytes
debug: uasc 10859/6: recv MSGF with 52 bytes
debug: uasc 10859/6: err: The session cannot be used because ActivateSession has not been called. StatusBadSessionNotActivated (0x80270000)
debug: uasc 10859/6: sending *ua.ServiceFault to handler
debug: client: monitor: updating namespaces failed: The session cannot be used because ActivateSession has not been called. StatusBadSessionNotActivated (0x80270000)

and we remain stuck in the reconnecting state (easier to see if you comment out debug flags: lines 13&14)

2023/08/17 16:21:09 INFO TICK v=2023-08-17T16:21:09.249+02:00
2023/08/17 16:21:09 INFO Reconnecting
2023/08/17 16:21:10 INFO TICK v=2023-08-17T16:21:10.249+02:00
2023/08/17 16:21:10 INFO Reconnecting
2023/08/17 16:21:11 INFO TICK v=2023-08-17T16:21:11.249+02:00
2023/08/17 16:21:11 INFO Reconnecting
2023/08/17 16:21:12 INFO TICK v=2023-08-17T16:21:12.249+02:00
2023/08/17 16:21:12 INFO Reconnecting
2023/08/17 16:21:13 INFO TICK v=2023-08-17T16:21:13.249+02:00
2023/08/17 16:21:13 INFO Reconnecting

It looks like ActivateSession is not properly called within the recreateSession action? For reason this is the error we get when it tries to updateNamespaces.

Not sure if this is a package issue, or an issue with our server.

Any feedback would be helpful! Thanks!

[law-dwg]

Any update here? Any support would be appreciated.

[mvandergrift]

@law-dwg We're running into this issue with a couple of different servers as well. Did you ever find a resolution?

I just started looking into the problem, I'll let you know if I find anything.

[magiconair]

@law-dwg I've just released v0.5.3 with the fix from @mvandergrift. Could you please check if this also fixes the problem you were seeing? Thank you!

[law-dwg]

Awesome, i just tested my above example, and it works flawlessly. Thanks so much @mvandergrift !