Regression: DID Exchange webhook state with "completed"

[dbluhm]

Connection records have two different state attributes: one reflecting the old states associated with the connection protocol and one for the DID Exchange protocol. These are state and rfc23_state respectively. The terminal state for the state attribute is active. The terminal state for rfc23_state is completed. Recently something changed and we now get a state of completed under certain circumstances.

A minimal example can be found here: https://github.com/Indicio-tech/acapy-minimal-example/tree/main/examples/simple

The example can be run by:

git clone https://github.com/Indicio-tech/acapy-minimal-example
cd examples/simple
docker-compose run example
# Don't forget to down when you're done
docker-compose down -v

The webhooks are printed to stdout under the DEBUG log level. Right at the end of the exchange, you will see:

[DEBUG] Bob: Event(topic='connections', payload={'created_at': '2023-08-18T18:35:51.295588Z', 'their_role': 'inviter', 'invitation_msg_id': '99d69030-2aaf-4371-8ff7-41031ee7f325', 'invitation_mode': 'once', 'their_did': 'LnqBDAaFbVHtrZcg3XV5KC', 'state': 'response', 'request_id': '66780853-ee45-4373-8efc-3b310b8fc48c', 'routing_state': 'none', 'connection_protocol': 'didexchange/1.0', 'updated_at': '2023-08-18T18:35:51.588161Z', 'invitation_key': 'A74AJiSaMdUkEbqhAVxJJt5vfD55Gz5fjNDGczHkJHrd', 'connection_id': '850787cf-73c4-4bbe-9de6-c4873596ec2a', 'their_label': 'Alice', 'rfc23_state': 'response-received', 'my_did': 'R4mLoWnMXLT2WYS2WS3wVy', 'accept': 'manual'}, wallet_id=None)
[DEBUG] Bob: Event(topic='connections', payload={'created_at': '2023-08-18T18:35:51.295588Z', 'their_role': 'inviter', 'invitation_msg_id': '99d69030-2aaf-4371-8ff7-41031ee7f325', 'invitation_mode': 'once', 'their_did': 'LnqBDAaFbVHtrZcg3XV5KC', 'state': 'completed', 'request_id': '66780853-ee45-4373-8efc-3b310b8fc48c', 'routing_state': 'none', 'connection_protocol': 'didexchange/1.0', 'updated_at': '2023-08-18T18:35:51.616411Z', 'invitation_key': 'A74AJiSaMdUkEbqhAVxJJt5vfD55Gz5fjNDGczHkJHrd', 'connection_id': '850787cf-73c4-4bbe-9de6-c4873596ec2a', 'their_label': 'Alice', 'rfc23_state': 'completed', 'my_did': 'R4mLoWnMXLT2WYS2WS3wVy', 'accept': 'manual'}, wallet_id=None)
[DEBUG] Alice: Event(topic='connections', payload={'accept': 'manual', 'request_id': '66780853-ee45-4373-8efc-3b310b8fc48c', 'created_at': '2023-08-18T18:35:51.246773Z', 'my_did': 'LnqBDAaFbVHtrZcg3XV5KC', 'updated_at': '2023-08-18T18:35:51.647941Z', 'state': 'active', 'connection_id': 'c6823c41-fd23-47f7-ba78-a7f61bbd651f', 'invitation_key': 'A74AJiSaMdUkEbqhAVxJJt5vfD55Gz5fjNDGczHkJHrd', 'connection_protocol': 'didexchange/1.0', 'their_label': 'Bob', 'rfc23_state': 'completed', 'their_did': 'R4mLoWnMXLT2WYS2WS3wVy', 'routing_state': 'none', 'invitation_mode': 'once', 'invitation_msg_id': '99d69030-2aaf-4371-8ff7-41031ee7f325', 'their_role': 'invitee'}, wallet_id=None)

This output is 3 webhook events:

1. Bob's state change to response
2. Bob's state change to completed <- This is the problematic webhook
3. Alice's state change to active -- This is the state Bob should have reached

These webhooks happen to have been received over websocket. Just to double check, I looked at posted webhook values as well (which can be seen with docker-compose logs webhook-listener in the docker-compose setup used for this example) and the same erroneous state is visible there.

When later querying Bob's connections, the returned records show the correct state of active instead of completed for the state attribute.

I believe this webhook is being emitted as Bob is sending the complete message to Alice after receiving Alice's response message.

We've seen this break at least one controller so far.

[dbluhm]

You can work around this by using the rfc23_state attribute and expecting the appropriate values for those states (request-sent, request-received, ..., completed, etc.).

[dbluhm]

@anwalker293 spotted the issue; in the DID Exchange protocol manager, the conn_record.state is getting set to ConnRecord.State.COMPLETED.rfc23 which is equal to the string completed. This follows the pattern used elsewhere in the manager but since the states happen to align (i.e. request for rfc160 is also request for rfc23), it wasn't obvious that this was incorrect.

conn_record.state should ALWAYS be set to the string for rfc160, whether it's getting set in the connections or did exchange protocols. I think we probably should have handled the state management for these protocols differently but we're here so this is the right fix for now.