Subscription handling in Kuksa.val

[nayakned]

It looks like the kuksa.val server is not deleting subscription sessions if the client dies before unsubscribing or forgets to unsubscribe.

Here a log. I ran a client session multiple times while subscribing for same data Vehicle.Speed. I didnt unsubscribe while the client terminated.

VERBOSE: SubscriptionHandler::update: set value "68" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 675526736SubscriptionHandler::update: set value "68" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 675407987SubscriptionHandler::update: set value "68" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 674175860SubscriptionHandler::update: set value "68" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 677776468SubscriptionHandler::update: set value "68" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 676432633SubscriptionHandler::update: set value "68" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 676451158SubscriptionHandler::update: set value "68" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 674637585SubscriptionHandler::update: set value "68" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9

The network sessions are being closed but the subscription sessions arent.

tcp        0      0 127.0.0.1:8090          0.0.0.0:*               LISTEN     
tcp        0      0 127.0.0.1:38784         127.0.0.1:8090          FIN_WAIT2  
tcp      143      0 127.0.0.1:8090          127.0.0.1:38784         CLOSE_WAIT 
tcp        0      0 127.0.0.1:38786         127.0.0.1:8090          FIN_WAIT2  
tcp      392      0 127.0.0.1:8090          127.0.0.1:38786         CLOSE_WAIT 

If you do this often enough, you see uncaught exceptions followed by termination of the websocket session.
Here some log snippets:

VERBOSE: Set request with id 3bcc85d7-e26c-4aec-9352-ce6252ca3317 for path: Vehicle.Speed
VERBOSE: SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 675747107SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 672065781SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 680383701SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 675526736SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 672493426SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 675585528SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 675407987SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 674175860SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 677776468SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 673002570SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 676432633SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 676451158SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 674637585SubscriptionHandler::update: set value "1" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
ERROR: read: unspecified system error
WARNING: JSON parse error

[nayakned]

Among the other uncaught exceptions while unsubscribing include

VERBOSE: SubscriptionHandler::update: set value "67" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 2215712691SubscriptionHandler::update: set value "67" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
corrupted size vs. prev_size

VERBOSE: SubscriptionHandler::update: set value "23" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 4168177328SubscriptionHandler::update: set value "23" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 4163800424SubscriptionHandler::update: set value "23" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 4167116607SubscriptionHandler::update: set value "23" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 4167692301SubscriptionHandler::update: set value "23" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 4165464252SubscriptionHandler::update: set value "23" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
free(): invalid pointer

VERBOSE: Set request with id 110313f7-a69e-4b70-9531-4ba9cce5fe84 for path: Vehicle.Speed
VERBOSE: SubscriptionHandler::update: set value "12" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 945668020SubscriptionHandler::update: set value "12" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
[1]    38703 segmentation fault (core dumped)  ./kuksa-val-server --insecure

VERBOSE: Set request with id 7eeb6ff2-564a-4bd9-8b05-18ebab0885b9 for path: Vehicle.Speed
VERBOSE: SubscriptionHandler::update: set value "42" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 2560792818: SubscriptionHandler::update: set value "42" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 2557374422: SubscriptionHandler::update: set value "42" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 2555976233: SubscriptionHandler::update: set value "42" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 2556820914: SubscriptionHandler::update: set value "42" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
VERBOSE: SubscriptionHandler::updateByUUID: new value set at path 2557883846: SubscriptionHandler::update: set value "42" for path Vehicle.Speed for UUID efe50798638d55fab18ab7d43cc490e9
double free or corruption (out)
[1]    6622 abort (core dumped)  ./kuksa-val-server --insecure

[nayakned]

The "unspecified system error" is perhaps stemming from boostorg/beast#1858

[SebastianSchildt]

Fixed