Controller Adapter Crash on Agent Reconnect (obuspa)

[sribce1]

Trying to connect Broadband OBUSPA agent to the controller.

Agent : Latest cloned code https://github.com/BroadbandForum/obuspa.git
Gerrit Id : f05221d3423ed45d53e761fc872a2a74a1fbb2a5
2025-06-24 v10.0.4: Bug Fixes

Tried to connect the Agent to Oktopus controller via STOMP and able to connect first time and saw Connect Successfull, Subscribe and Got GET request from controller.
Please find the log snippet for the first session:

_> obuspa -p -v 5 -r ~/Projects/TR369/Test/obuspa_oktopus_stomp.txt -i lo -d ~/Projects/TR369/Test/agent_usp.db
DATABASE_Init: Opening database /home/user/Projects/TR369/Test/agent_usp.db
ResetFactoryParametersFromFile: Setting factory reset parameters
LoadClientCert: Not using a device certificate for connections
CLI_SERVER_Init: Starting CLI server on /tmp/usp_cli
Attempting to connect to host=localhost (ipaddr=127.0.0.1, port=61613, unencrypted) from interface=lo
Connected to 127.0.0.1 (host=localhost, port=61613) from interface=lo
Sending STOMP frame to (host=localhost, port=61613)
STOMP
accept-version:1.2
host:/
endpoint-id:obuspa_user
login:admin
passcode:

Received CONNECTED frame from (host=localhost, port=61613)
CONNECTED
version:1.2
server:stompd/1.2
heart-beat:0,0
subscribe-dest:oktopus/usp/v1/agent/obuspa_user

Sending SUBSCRIBE frame to (host=localhost, port=61613)
SUBSCRIBE
id:0
destination:oktopus/usp/v1/agent/obuspa_user
ack:auto

Message received at time 2025-07-15T05:47:40Z, from host localhost over STOMP
MESSAGE
content-length:261
destination:oktopus/usp/v1/agent/obuspa_user
content-type:application/vnd.bbf.usp.msg
reply-to-dest:oktopus/usp/v1/controller/obuspa_user/info
subscription:0
message-id:1
id:1
version: "1.0"
to_id: "obuspa_user"
from_id: "oktopusController"
payload_security: PLAINTEXT
mac_signature[0]
sender_cert[0]
no_session_context {
payload[216]
}

header {
msg_id: "89f55bee-9d43-48ef-b91b-86004050c424"
msg_type: GET
}
body {
request {
get {
param_paths: "Device.DeviceInfo.Manufacturer"
param_paths: "Device.DeviceInfo.ModelName"
param_paths: "Device.DeviceInfo.SoftwareVersion"
param_paths: "Device.DeviceInfo.SerialNumber"
param_paths: "Device.DeviceInfo.ProductClass"
max_depth: 1
}
}
}

GET : processing at time 2025-07-15T05:47:40Z
DM_PRIV_CheckGetReadPermissions: Invalid path
DM_PRIV_CheckGetReadPermissions: Invalid path
DM_PRIV_CheckGetReadPermissions: Invalid path
DM_PRIV_CheckGetReadPermissions: Invalid path
DM_PRIV_CheckGetReadPermissions: Invalid path

GET_RESP sending at time 2025-07-15T05:47:40Z, to host localhost over STOMP
SEND
content-length:526
content-type:application/vnd.bbf.usp.msg
reply-to-dest:oktopus/usp/v1/agent/obuspa_user
destination:oktopus/usp/v1/controller/obuspa_user/info
version: "1.3"
to_id: "oktopusController"
from_id: "obuspa_user"
payload_security: PLAINTEXT
mac_signature[0]
sender_cert[0]
no_session_context {
payload[481]
}

header {
msg_id: "89f55bee-9d43-48ef-b91b-86004050c424"
msg_type: GET_RESP
}
body {
response {
get_resp {
req_path_results {
requested_path: "Device.DeviceInfo.Manufacturer"
err_code: 7026
err_msg: "DM_PRIV_CheckGetReadPermissions: Invalid path"
}
req_path_results {
requested_path: "Device.DeviceInfo.ModelName"
err_code: 7026
err_msg: "DM_PRIV_CheckGetReadPermissions: Invalid path"
}
req_path_results {
requested_path: "Device.DeviceInfo.SoftwareVersion"
err_code: 7026
err_msg: "DM_PRIV_CheckGetReadPermissions: Invalid path"
}
req_path_results {
requested_path: "Device.DeviceInfo.SerialNumber"
err_code: 7026
err_msg: "DM_PRIV_CheckGetReadPermissions: Invalid path"
}
req_path_results {
requested_path: "Device.DeviceInfo.ProductClass"
err_code: 7026
err_msg: "DM_PRIV_CheckGetReadPermissions: Invalid path"
}
}
}
}_

---

Force Stopped the Agent and tried to connect to controller again, but this time After Subscribe frame there is no Response form Controller side.

---

^C
user@UbuntuLTS24:~/Projects/TR369/Test/obuspa$ rm -rf /Projects/TR369/Test/agent_usp.db
user@UbuntuLTS24:/Projects/TR369/Test/obuspa$ obuspa -p -v 5 -r ~/Projects/TR369/Test/obuspa_oktopus_stomp.txt -i lo -d ~/Projects/TR369/Test/agent_usp.db
DATABASE_Init: Opening database /home/user/Projects/TR369/Test/agent_usp.db
ResetFactoryParametersFromFile: Setting factory reset parameters
LoadClientCert: Not using a device certificate for connections
Attempting to connect to host=localhost (ipaddr=127.0.0.1, port=61613, unencrypted) from interface=lo
Connected to 127.0.0.1 (host=localhost, port=61613) from interface=lo
Sending STOMP frame to (host=localhost, port=61613)
STOMP
accept-version:1.2
host:/
endpoint-id:obuspa_user
login:admin
passcode:

CLI_SERVER_Init: Starting CLI server on /tmp/usp_cli
Received CONNECTED frame from (host=localhost, port=61613)
CONNECTED
version:1.2
server:stompd/1.2
heart-beat:0,0
subscribe-dest:oktopus/usp/v1/agent/obuspa_user

Sending SUBSCRIBE frame to (host=localhost, port=61613)
SUBSCRIBE
id:0
destination:oktopus/usp/v1/agent/obuspa_user
ack:auto

^C

---

It was NOT clear why the Controller didnt respond this time ( even though there is No Device details sent by Agent, atleast the GET DeviceInfo request should be honoured )

At Controller side for adapter following logs are observed (docker logs adapter).

---

_025/07/15 05:43:37 Error to load environment variables: open .env: no such file or directory
2025/07/15 05:43:37 nats.go:154: Load certificates: /tmp/nats/config/cert.pem and /tmp/nats/config/key.pem
2025/07/15 05:43:37 nats.go:37: Connecting to NATS server nats://oktopususer:oktopuspw@msg_broker:4222
2025/07/15 05:43:37 nats.go:47: Successfully connected to NATS server nats://oktopususer:oktopuspw@msg_broker:4222
2025/07/15 05:43:37 db.go:30: Trying to ping Mongo database...
2025/07/15 05:43:41 db.go:36: Connected to MongoDB--> mongodb://mongo_usp:27017
2025/07/15 05:43:41 events.go:16: Listening for nats events
2025/07/15 05:43:41 reqs.go:25: Listening for nats requests
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:60: Device obuspa_useris offline
2025/07/15 05:43:41 status.go:18: mongo: no documents in result
2025/07/15 05:43:41 status.go:69: obuspa_user is now offline.
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:32: Device obuspa_user is online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:60: Device obuspa_user is offline
2025/07/15 05:43:41 status.go:18: mongo: no documents in result
2025/07/15 05:43:41 status.go:69: obuspa_user is now offline.
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user .status
2025/07/15 05:43:41 status.go:32: Device obuspa_user is online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:60: Device obuspa_user is offline
2025/07/15 05:43:41 status.go:18: mongo: no documents in result
2025/07/15 05:43:41 status.go:69: obuspa_useris now offline.
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user .status
2025/07/15 05:43:41 status.go:32: Device obuspa_useris online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user .status
2025/07/15 05:43:41 status.go:60: Device obuspa_useris offline
2025/07/15 05:43:41 status.go:18: mongo: no documents in result
2025/07/15 05:43:41 status.go:69: obuspa_useris now offline.
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user .status
2025/07/15 05:43:41 status.go:32: Device obuspa_useris online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user .status
2025/07/15 05:43:41 status.go:32: Device obuspa_useris online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:60: Device obuspa_useris offline
2025/07/15 05:43:41 status.go:18: mongo: no documents in result
2025/07/15 05:43:41 status.go:69: obuspa_useris now offline.
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:32: Device obuspa_useris online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:60: Device obuspa_useris offline
2025/07/15 05:43:41 status.go:18: mongo: no documents in result
2025/07/15 05:43:41 status.go:69: obuspa_useris now offline.
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:32: Device obuspa_useris online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:60: Device obuspa_useris offline
2025/07/15 05:43:41 status.go:18: mongo: no documents in result
2025/07/15 05:43:41 status.go:69: obuspa_useris now offline.
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:32: Device obuspa_useris online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:32: Device obuspa_useris online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:60: Device obuspa_useris offline
2025/07/15 05:43:41 status.go:18: mongo: no documents in result
2025/07/15 05:43:41 status.go:69: obuspa_useris now offline.
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:32: Device obuspa_useris online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:60: Device obuspa_useris offline
2025/07/15 05:43:41 status.go:18: mongo: no documents in result
2025/07/15 05:43:41 status.go:69: obuspa_useris now offline.
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:32: Device obuspa_useris online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:32: Device obuspa_useris online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:60: Device obuspa_useris offline
2025/07/15 05:43:41 status.go:18: mongo: no documents in result
2025/07/15 05:43:41 status.go:69: obuspa_useris now offline.
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:32: Device obuspa_useris online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:60: Device obuspa_useris offline
2025/07/15 05:43:41 status.go:18: mongo: no documents in result
2025/07/15 05:43:41 status.go:69: obuspa_useris now offline.
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:32: Device obuspa_useris online
2025/07/15 05:43:41 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:43:41 status.go:60: Device obuspa_useris offline
2025/07/15 05:43:41 status.go:18: mongo: no documents in result
2025/07/15 05:43:41 status.go:69: obuspa_useris now offline.
2025/07/15 05:47:40 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.status
2025/07/15 05:47:40 status.go:32: Device obuspa_useris online
2025/07/15 05:47:40 events.go:46: Received message, subject: stomp.usp.v1.obuspa_user.info
2025/07/15 05:47:40 info.go:16: Device obuspa_userinfo, mtp: stomp
panic: runtime error: index out of range [0] with length 0

goroutine 97 [running]:
github.com/OktopUSP/oktopus/backend/services/mtp/adapter/internal/events/usp_handler.parseDeviceInfoMsg({0xc00014860d, 0xd}, {0x4670fd?, 0x0?}, {0xc000524000, 0x20e, 0x20e}, 0x2)
/app/internal/events/usp_handler/info.go:57 +0x465
github.com/OktopUSP/oktopus/backend/services/mtp/adapter/internal/events/usp_handler.(*Handler).HandleDeviceInfo(0xc0003a0410, {0xc00014860d, 0xd}, {0xc000148600, 0x1f}, {0xc000524000, 0x20e, 0x20e}, {0xa75bf6, 0x5}, ...)
/app/internal/events/usp_handler/info.go:17 +0x20e
github.com/OktopUSP/oktopus/backend/services/mtp/adapter/internal/events.StartEventsListener.func1({0xa75bf6, 0x5})
/app/internal/events/events.go:56 +0x454
created by github.com/OktopUSP/oktopus/backend/services/mtp/adapter/internal/events.StartEventsListener in goroutine 1
/app/internal/events/events.go:27 +0x233_

---

We can observe that "panic: runtime error: index out of range" issue observed in info.go file during parseDeviceInfoMsg function.

Why is this happening? why adapter was not able to handle the agent's reconnect behavior gracefully. It's likely failing to correctly reset its internal state for the given endpoint-id and is making a wrong assumption about the content of the message received from the agent.