aws/aws-iot-device-sdk-python-v2

Release v1.11.0 - ECC key (PKCS11) - pkcs11_connect.py - mqtt_connection is NoneType

sckulkarni246 opened this issue · 3 comments

sckulkarni246 commented

Describe the bug

  • The release v1.11.0 added ECC key support for PKCS#11 implementations.
  • pip freeze output is as below
awscrt==0.13.9
awsiotsdk==1.11.0
  • The sample app called pkcs11_connect.py fails with the error as below.
Traceback (most recent call last):
  File "pkcs11_connect.py", line 56, in <module>
    connect_future = mqtt_connection.connect()
AttributeError: 'NoneType' object has no attribute 'connect'
  • The trace log (application output with --verbosity Trace) is provided in the Current Behavior section

Expected Behavior

The expectation was that the MQTT connection would be successful thus successfully demonstrating successful PKCS#11 ECC key usage to connect to AWS IoT.

Current Behavior

The calls to and the trace output of the pkcs11_connect.py application is as below.

NOTE

  • rpi_test_1.crt is the device certificate generated by AWS IoT Core upon uploading a CSR - the CSR is generated using the PKCS#11 engine
  • rpi_tngtls_1 is the thing name
  • The PKCS#11 library is checked for connectivity to engine using p11tool beforehand

Call to the sample app

$ python3 pkcs11_connect.py --endpoint a************-ats.iot.us-west-2.amazonaws.com --cert ~/rpi_test_1.crt --pkcs11_lib /usr/lib/libcryptoauth.so --token_label 00ABC --key_label device --pin 1234 --client_id rpi_tngtls_1 --port 8883 --client_id rpi_tngtls_1 --ca_file ~/AmazonRootCA1.pem --verbosity Trace

Trace Output

Loading PKCS#11 library '/usr/lib/libcryptoauth.so' ...
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [pkcs11] - Loading PKCS#11. file:'/usr/lib/libcryptoauth.so' C_Initialize:yes
[INFO] [2022-04-20T09:57:52Z] [b6f8c010] [pkcs11] - id=0xa64be0: PKCS#11 loaded. file:'/usr/lib/libcryptoauth.so' cryptokiVersion:2.40 manufacturerID:'Microchip Technology Inc' flags:0x00000000 libraryDescription:'Cryptoauthlib PKCS11 Interface' libraryVersion:3.3 C_Initialize:CKR_OK
Loaded!
[INFO] [2022-04-20T09:57:52Z] [b6f8c010] [event-loop] - id=0xb44360: Initializing edge-triggered epoll
[INFO] [2022-04-20T09:57:52Z] [b6f8c010] [event-loop] - id=0xb44360: Using eventfd for cross-thread notifications.
[TRACE] [2022-04-20T09:57:52Z] [b6f8c010] [event-loop] - id=0xb44360: eventfd descriptor 5.
[INFO] [2022-04-20T09:57:52Z] [b6f8c010] [event-loop] - id=0xb44360: Starting event-loop thread.
[INFO] [2022-04-20T09:57:52Z] [b6f8c010] [event-loop] - id=0xb33480: Initializing edge-triggered epoll
[INFO] [2022-04-20T09:57:52Z] [b6f8c010] [event-loop] - id=0xb33480: Using eventfd for cross-thread notifications.
[TRACE] [2022-04-20T09:57:52Z] [b6f8c010] [event-loop] - id=0xb33480: eventfd descriptor 7.
[INFO] [2022-04-20T09:57:52Z] [b6f8c010] [event-loop] - id=0xb33480: Starting event-loop thread.
[INFO] [2022-04-20T09:57:52Z] [b505a450] [event-loop] - id=0xb44360: main loop started
[TRACE] [2022-04-20T09:57:52Z] [b505a450] [event-loop] - id=0xb44360: subscribing to events on fd 5
[INFO] [2022-04-20T09:57:52Z] [b6f8c010] [dns] - id=0xa35810: Initializing default host resolver with 16 max host entries.
[INFO] [2022-04-20T09:57:52Z] [b4659450] [event-loop] - id=0xb33480: main loop started
[TRACE] [2022-04-20T09:57:52Z] [b4659450] [event-loop] - id=0xb33480: subscribing to events on fd 7
[INFO] [2022-04-20T09:57:52Z] [b4659450] [event-loop] - id=0xb33480: default timeout 100000, and max events to process per tick 100
[TRACE] [2022-04-20T09:57:52Z] [b4659450] [event-loop] - id=0xb33480: waiting for a maximum of 100000 ms
[INFO] [2022-04-20T09:57:52Z] [b6f8c010] [channel-bootstrap] - id=0xb20128: Initializing client bootstrap with event-loop group 0xa7b658
[INFO] [2022-04-20T09:57:52Z] [b505a450] [event-loop] - id=0xb44360: default timeout 100000, and max events to process per tick 100
[TRACE] [2022-04-20T09:57:52Z] [b505a450] [event-loop] - id=0xb44360: waiting for a maximum of 100000 ms
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [tls-handler] - ctx: PKCS#11 has been set, setting it up now.
[TRACE] [2022-04-20T09:57:52Z] [b6f8c010] [pkcs11] - id=0xa64be0: Found 1 slots with tokens. Picking one...
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [pkcs11] - id=0xa64be0: Selected PKCS#11 token. slot:0 label:'00ABC' manufacturerID:'Microchip Technology Inc' model:'ATECC608A' serialNumber:'231606F750596A01' flags:0x00000401 sessionCount:0/1 rwSessionCount:0/1 freePublicMemory:4294967295/4294967295 freePrivateMemory:4294967295/4294967295 hardwareVersion:0.2 firmwareVersion:255.255
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [pkcs11] - id=0xa64be0 session=11475664: Session opened on slot 0
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [pkcs11] - id=0xa64be0 session=11475664: User logged in
[TRACE] [2022-04-20T09:57:52Z] [b6f8c010] [pkcs11] - id=0xa64be0 session=11475664: Found private key. type=CKK_EC
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [mqtt-client] - client=0xa8e900: Initalizing MQTT client
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [mqtt-client] - id=0xa3c4b8: Creating new connection
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [mqtt-topic-tree] - tree=0xa3c624: Creating new topic tree
[TRACE] [2022-04-20T09:57:52Z] [b6f8c010] [mqtt-client] - id=0xa3c4b8: Setting connection interrupted and resumed handlers
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [mqtt-client] - id=0xa3c4b8: user called disconnect.
[ERROR] [2022-04-20T09:57:52Z] [b6f8c010] [mqtt-client] - id=0xa3c4b8: Connection is not open, and may not be closed
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [mqtt-client] - id=0xa3c4b8: Last refcount on connection has been released, start destroying the connection.
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [mqtt-client] - id=0xa3c4b8: Destroying connection
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [mqtt-topic-tree] - tree=0xa3c624: Cleaning up topic tree
[TRACE] [2022-04-20T09:57:52Z] [b6f8c010] [mqtt-topic-tree] - node=0xa69690: Destroying topic tree node
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [mqtt-client] - client=0xa8e900: Cleaning up MQTT client
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [channel-bootstrap] - id=0xb20128: releasing bootstrap reference
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [pkcs11] - id=0xa64be0 session=11475664: Session closed
[DEBUG] [2022-04-20T09:57:52Z] [b6f8c010] [pkcs11] - id=0xa64be0: Unloading PKCS#11. C_Finalize:yes
Connecting to a************-ats.iot.us-west-2.amazonaws.com with client ID 'rpi_tngtls_1'...
Traceback (most recent call last):
  File "pkcs11_connect.py", line 56, in <module>
    connect_future = mqtt_connection.connect()
AttributeError: 'NoneType' object has no attribute 'connect'

Reproduction Steps

Installation and execution of the sample application was done as below.

$ python3 -m venv vpython3
$ . vpython3/bin/activate
(vpython3) $ pip install awsiotsdk==1.11.0
(vpython3) $ cd path/to/samples/folder
(vpython3) $ python3 pkcs11_connect.py --endpoint a************-ats.iot.us-west-2.amazonaws.com --cert ~/rpi_test_1.crt --pkcs11_lib /usr/lib/libcryptoauth.so --token_label 00ABC --key_label device --pin 1234 --client_id rpi_tngtls_1 --port 8883 --client_id rpi_tngtls_1 --ca_file ~/AmazonRootCA1.pem --verbosity Trace

Possible Solution

I don't know what may be causing this :-/

Additional Information/Context

  • The PKCS#11 engine is Microchip's ATECC608-TNGTLS chip.
  • The cryptoauthlib version is v3.3.3.
  • Mutual TLS authentication between a dummy server and ATECC608-TNGTLS based client (OpenSSL PKCS#11 engine) has been tested to establish successfully. The process followed for this is documented here.

SDK version used

1.11.0

Environment details (OS name and version, etc.)

Raspbian GNU/Linux 10 (buster)

graebm commented

Fixed in main

graebm commented

Thanks for the excellent write-up by the way. The logs were really helpful

  • 👍1
sckulkarni246 commented

Thanks for the excellent write-up by the way. The logs were really helpful

Welcome and thanks to you all for all the great work and the excellent support always!