search

atsign-foundation / at_libraries

Support libraries & dependencies for Atsign's technology
https://pub.dev/publishers/atsign.org/packages
BSD 3-Clause "New" or "Revised" License
38 stars 11 forks source link

authentication with sync enabled failing if pkam is in secure element #351

Closed murali-shris closed 1 year ago

murali-shris commented 1 year ago

Describe the bug

Authentication for sync is failing while using at_chops with pkam in secure element

Steps to reproduce

INFO|2023-05-25 15:10:27.882773|AtClientManager|setCurrentAtSign called with atSign @atsign00001

INFO|2023-05-25 15:10:27.885375|AtClientManager|Switching atSigns from null to @atsign00001

INFO|2023-05-25 15:10:28.028985|HiveBase|commit_log_fe9a999d3c21f3a452c9b093da952366f11c4ff35c4c4e06c2a77507927d984c initialized successfully

FINER|2023-05-25 15:10:28.043306|CommitLogKeyStore|last committed sequence: 1

INFO|2023-05-25 15:10:28.108487|HiveBase|fe9a999d3c21f3a452c9b093da952366f11c4ff35c4c4e06c2a77507927d984c initialized successfully

INFO|2023-05-25 15:10:28.217627|AtClientCommitLogCompaction (@atsign00001)|Starting commit log compaction job running for every 11 minute(s)

FINER|2023-05-25 15:10:28.523215|NotificationServiceImpl (@atsign00001)|subscribe(regex: statsNotification, shouldDecrypt: false

INFO|2023-05-25 15:10:28.538937|AtClientManager|setCurrentAtSign complete

FINER|2023-05-25 15:10:28.542328|OnboardingCli|pkam auth

INFO|2023-05-25 15:10:28.571275|AtLookup|Creating new connection

FINER|2023-05-25 15:10:28.577146|AtLookup|AtLookup.findSecondary received atsign: atsign00001

FINER|2023-05-25 15:10:29.244927|AtLookup|AtLookup.findSecondary got answer: a2b8a567-a43a-5f67-a8f1-3d50ae5b5184.staging0001.atsign.zone:1024 and closing connection

INFO|2023-05-25 15:10:29.491679|AtLookup|New connection created OK

FINER|2023-05-25 15:10:29.523577|AtLookup|SENDING: from:@atsign00001:clientConfig:{"version":"3.0.58"}

FINER|2023-05-25 15:10:29.645026|OutboundMessageListener|RECEIVED data:_5f6dc9a9-6a2e-43eb-ba51-0afcd5f3ed4d@atsign00001:3458b38d-3196-43d6-8a8e-3540261d380e

FINER|2023-05-25 15:10:29.651558|AtLookup|from result:data:_5f6dc9a9-6a2e-43eb-ba51-0afcd5f3ed4d@atsign00001:3458b38d-3196-43d6-8a8e-3540261d380e

FINER|2023-05-25 15:10:29.653231|AtLookup|fromResponse _5f6dc9a9-6a2e-43eb-ba51-0afcd5f3ed4d@atsign00001:3458b38d-3196-43d6-8a8e-3540261d380e

FINER|2023-05-25 15:10:29.654400|AtLookup|signingAlgoType: SigningAlgoType.ecc_secp256r1 hashingAlgoType:HashingAlgoType.sha256

INFO|2023-05-25 15:10:30.705094|ExternalSigner|opened logical channel #:01

INFO|2023-05-25 15:10:31.711776|ExternalSigner|selected IOTSafe application

INFO|2023-05-25 15:10:32.716483|ExternalSigner|computeSignatureInitResult :AT+CSIM=40,"812A00010F8403303036A1010391020001920104" +CSIM: 4,"9000"

OK

INFO|2023-05-25 15:10:42.732048|ExternalSigner|signature computed. Retrieving the signature

INFO|2023-05-25 15:10:43.739077|ExternalSigner|signature: 330040DC6B198999DFAEEE77513983E8292DCC519B7757D691E7D975CA46400C6E7D4BCD30306BBB9809FE1DD79219DA33E3A30BBD7FD69D2201AA8ACACB6F10FDF2CB9000

FINER|2023-05-25 15:10:44.764701|AtLookup|pkamCommand:pkam:signingAlgo:ecc_secp256r1:hashingAlgo:sha256:ZGM2YjE5ODk5OWRmYWVlZTc3NTEzOTgzZTgyOTJkY2M1MTliNzc1N2Q2OTFlN2Q5NzVjYTQ2NDAwYzZlN2Q0YmNkMzAzMDZiYmI5ODA5ZmUxZGQ3OTIxOWRhMzNlM2EzMGJiZDdmZDY5ZDIyMDFhYThhY2FjYjZmMTBmZGYyY2I=

FINER|2023-05-25 15:10:44.765533|AtLookup|SENDING: pkam:signingAlgo:ecc_secp256r1:hashingAlgo:sha256:ZGM2YjE5ODk5OWRmYWVlZTc3NTEzOTgzZTgyOTJkY2M1MTliNzc1N2Q2OTFlN2Q5NzVjYTQ2NDAwYzZlN2Q0YmNkMzAzMDZiYmI5ODA5ZmUxZGQ3OTIxOWRhMzNlM2EzMGJiZDdmZDY5ZDIyMDFhYThhY2FjYjZmMTBmZGYyY2I=

FINER|2023-05-25 15:10:44.883218|OutboundMessageListener|RECEIVED data:success

INFO|2023-05-25 15:10:44.887365|AtLookup|auth success

FINER|2023-05-25 15:10:44.890473|OnboardingCli|pkam auth result: true

FINER|2023-05-25 15:10:45.092966|OnboardingCli|PkamPublicKey persist to localSecondary: status true

FINER|2023-05-25 15:10:45.151601|OnboardingCli|EncryptionPublicKey persist to localSecondary: status true

FINER|2023-05-25 15:10:45.197839|OnboardingCli|EncryptionPrivateKey persist to localSecondary: status true

FINER|2023-05-25 15:10:45.206266|OnboardingCli|Self encryption key persist to localSecondary: status true

INFO|2023-05-25 15:10:45.206721|OnboardSecureElement|auth done

FINER|2023-05-25 15:10:50.034408|AtLookup|calling pkam using atchops

INFO|2023-05-25 15:10:50.035069|AtLookup|Creating new connection

INFO|2023-05-25 15:10:50.257058|AtLookup|New connection created OK

FINER|2023-05-25 15:10:50.258043|AtLookup|SENDING: from:@atsign00001:clientConfig:{"version":"3.0.58"}

FINER|2023-05-25 15:10:50.366849|OutboundMessageListener|RECEIVED data:_27c28527-9463-4407-8aa9-d9e3ca821b79@atsign00001:d165dd0f-076e-47ee-9355-395c3813e2a7

FINER|2023-05-25 15:10:50.368322|AtLookup|from result:data:_27c28527-9463-4407-8aa9-d9e3ca821b79@atsign00001:d165dd0f-076e-47ee-9355-395c3813e2a7

FINER|2023-05-25 15:10:50.368659|AtLookup|fromResponse _27c28527-9463-4407-8aa9-d9e3ca821b79@atsign00001:d165dd0f-076e-47ee-9355-395c3813e2a7

FINER|2023-05-25 15:10:50.368840|AtLookup|signingAlgoType: SigningAlgoType.rsa2048 hashingAlgoType:HashingAlgoType.sha256

INFO|2023-05-25 15:10:51.374826|ExternalSigner|opened logical channel #:01

INFO|2023-05-25 15:10:52.377770|ExternalSigner|selected IOTSafe application

INFO|2023-05-25 15:10:53.380708|ExternalSigner|computeSignatureInitResult :AT+CSIM=40,"812A00010F8403303036A1010391020001920104" +CSIM: 4,"9000"

OK

INFO|2023-05-25 15:11:03.388920|ExternalSigner|signature computed. Retrieving the signature

INFO|2023-05-25 15:11:04.394143|ExternalSigner|signature: 33004044B7F9E163F8B328FD7F0D238A4BFB07B4FCCDA1513002CD5C229C467B40C3A5C8783B797597A557E69110834CC91A3F9026DC59F1CE0BB9BB0C8B6DEAA4083A9000

FINER|2023-05-25 15:11:05.397270|AtLookup|pkamCommand:pkam:signingAlgo:rsa2048:hashingAlgo:sha256:NDRiN2Y5ZTE2M2Y4YjMyOGZkN2YwZDIzOGE0YmZiMDdiNGZjY2RhMTUxMzAwMmNkNWMyMjljNDY3YjQwYzNhNWM4NzgzYjc5NzU5N2E1NTdlNjkxMTA4MzRjYzkxYTNmOTAyNmRjNTlmMWNlMGJiOWJiMGM4YjZkZWFhNDA4M2E=

FINER|2023-05-25 15:11:05.397816|AtLookup|SENDING: pkam:signingAlgo:rsa2048:hashingAlgo:sha256:NDRiN2Y5ZTE2M2Y4YjMyOGZkN2YwZDIzOGE0YmZiMDdiNGZjY2RhMTUxMzAwMmNkNWMyMjljNDY3YjQwYzNhNWM4NzgzYjc5NzU5N2E1NTdlNjkxMTA4MzRjYzkxYTNmOTAyNmRjNTlmMWNlMGJiOWJiMGM4YjZkZWFhNDA4M2E=

FINER|2023-05-25 15:11:05.403951|NotificationServiceImpl (@atsign00001)|@atsign00001 notification service _init()

FINER|2023-05-25 15:11:05.507189|OutboundMessageListener|RECEIVED error:{"errorCode":"AT0401","errorDescription":"Exception: pkam authentication failed"}

SEVERE|2023-05-25 15:11:05.521637|AtLookup|Error in remote verb execution Exception: Failed connecting to @atsign00001. error:{"errorCode":"AT0401","errorDescription":"Exception: pkam authentication failed"}

SEVERE|2023-05-25 15:11:05.532511|SyncUtil|Exception while getting latest server commit id: Exception: Exception: Failed connecting to @atsign00001. error:{"errorCode":"AT0401","errorDescription":"Exception: pkam authentication failed"}

SEVERE|2023-05-25 15:11:05.536247|SyncService (@atsign00001)|Exception in sync fff61425-f48b-408f-ad1a-70af0a1cadff. Reason: Failed to syncData caused by Unable to fetch latest server commit id: Exception: Exception: Failed connecting to @atsign00001. error:{"errorCode":"AT0401","errorDescription":"Exception: pkam authentication failed"}

SEVERE|2023-05-25 15:11:05.538923|SyncService (@atsign00001)|system sync error Unable to fetch latest server commit id: Exception: Exception: Failed connecting to @atsign00001. error:{"errorCode":"AT0401","errorDescription":"Exception: pkam authentication failed"}

FINER|2023-05-25 15:11:05.544178|SyncService (@atsign00001)|Informing 0 listeners of SyncProgress{atSign: @atsign00001, syncStatus: SyncStatus.failure, isInitialSync: false, startedAt: 2023-05-25 14:10:50.001564Z, completedAt: 2023-05-25 14:11:05.540804Z, message: null, keyInfoList:null, localCommitIdBeforeSync:null, localCommitId:null, serverCommitId:null}

FINER|2023-05-25 15:11:05.780600|Monitor (@atsign00001)|RECEIVED data:_d9cb2f03-5fac-40a7-ba7d-961a43ec2852@atsign00001:d2c55962-5be6-4afb-b192-7c9ca8323c67

FINER|2023-05-25 15:11:05.782202|Monitor (@atsign00001)|received response on monitor: data:_d9cb2f03-5fac-40a7-ba7d-961a43ec2852@atsign00001:d2c55962-5be6-4afb-b192-7c9ca8323c67

FINER|2023-05-25 15:11:05.786230|Monitor (@atsign00001)|Authenticating the monitor connection: from result:_d9cb2f03-5fac-40a7-ba7d-961a43ec2852@atsign00001:d2c55962-5be6-4afb-b192-7c9ca8323c67

FINER|2023-05-25 15:11:05.786990|Monitor (@atsign00001)|Using AtChops to do the PKAM signing

INFO|2023-05-25 15:11:05.795419|Monitor (@atsign00001)|socket.listen onDone called. Will destroy socket, set status stopped, call retryCallback

FINER|2023-05-25 15:11:05.800330|NotificationServiceImpl (@atsign00001)|monitor retry for @atsign00001

INFO|2023-05-25 15:11:05.802003|Monitor (@atsign00001)|Monitor error Null check operator used on a null value - calling the retryCallback

INFO|2023-05-25 15:11:05.802459|NotificationServiceImpl (@atsign00001)|Monitor retry already queued

FINER|2023-05-25 15:11:05.803631|NotificationServiceImpl (@atsign00001)|@atsign00001 monitor status: MonitorStatus.errored

FINER|2023-05-25 15:11:05.824627|NotificationServiceImpl (@atsign00001)|@atsign00001 starting monitor through connectivity listener event

FINER|2023-05-25 15:11:06.167612|Monitor (@atsign00001)|RECEIVED data:_6e295199-b9fb-41a4-a1d2-9f2ce433cce5@atsign00001:f52235d0-7a5f-4e1d-9555-4397a6eb422d

FINER|2023-05-25 15:11:06.167980|Monitor (@atsign00001)|received response on monitor: data:_6e295199-b9fb-41a4-a1d2-9f2ce433cce5@atsign00001:f52235d0-7a5f-4e1d-9555-4397a6eb422d

FINER|2023-05-25 15:11:06.168979|Monitor (@atsign00001)|Authenticating the monitor connection: from result:_6e295199-b9fb-41a4-a1d2-9f2ce433cce5@atsign00001:f52235d0-7a5f-4e1d-9555-4397a6eb422d

FINER|2023-05-25 15:11:06.169445|Monitor (@atsign00001)|Using AtChops to do the PKAM signing

INFO|2023-05-25 15:11:06.170559|Monitor (@atsign00001)|socket.listen onDone called. Will destroy socket, set status stopped, call retryCallback

INFO|2023-05-25 15:11:06.170902|NotificationServiceImpl (@atsign00001)|Monitor retry already queued

INFO|2023-05-25 15:11:06.171353|Monitor (@atsign00001)|Monitor error Null check operator used on a null value - calling the retryCallback

INFO|2023-05-25 15:11:06.171629|NotificationServiceImpl (@atsign00001)|Monitor retry already queued

FINER|2023-05-25 15:11:08.463651|AtCompactionStats|AtCommitLog: {"atCompactionType":"AtCommitLog","lastCompactionRun":"2023-05-25 14:11:08.458225Z","compactionDurationInMills":"18","preCompactionEntriesCount":"3","postCompactionEntriesCount":"3","deletedKeysCount":"0"}

FINER|2023-05-25 15:11:11.146856|Monitor (@atsign00001)|RECEIVED data:_94f21eaa-bde4-4ff6-80d2-6db5c89c90a9@atsign00001:958383f5-4850-4253-abca-f0900095994c

FINER|2023-05-25 15:11:11.147222|Monitor (@atsign00001)|received response on monitor: data:_94f21eaa-bde4-4ff6-80d2-6db5c89c90a9@atsign00001:958383f5-4850-4253-abca-f0900095994c

FINER|2023-05-25 15:11:11.148208|Monitor (@atsign00001)|Authenticating the monitor connection: from result:_94f21eaa-bde4-4ff6-80d2-6db5c89c90a9@atsign00001:958383f5-4850-4253-abca-f0900095994c

FINER|2023-05-25 15:11:11.148533|Monitor (@atsign00001)|Using AtChops to do the PKAM signing

INFO|2023-05-25 15:11:11.149724|Monitor (@atsign00001)|socket.listen onDone called. Will destroy socket, set status stopped, call retryCallback

FINER|2023-05-25 15:11:11.150085|NotificationServiceImpl (@atsign00001)|monitor retry for @atsign00001

INFO|2023-05-25 15:11:11.150580|Monitor (@atsign00001)|Monitor error Null check operator used on a null value - calling the retryCallback

INFO|2023-05-25 15:11:11.150857|NotificationServiceImpl (@atsign00001)|Monitor retry already queued

FINER|2023-05-25 15:11:16.501123|Monitor (@atsign00001)|RECEIVED data:_0583ab42-9462-4d4b-8e88-7af9041944b6@atsign00001:5ddc84dc-fc1b-4544-bfe7-d85ea195db4b

FINER|2023-05-25 15:11:16.501403|Monitor (@atsign00001)|received response on monitor: data:_0583ab42-9462-4d4b-8e88-7af9041944b6@atsign00001:5ddc84dc-fc1b-4544-bfe7-d85ea195db4b

FINER|2023-05-25 15:11:16.504391|Monitor (@atsign00001)|Authenticating the monitor connection: from result:_0583ab42-9462-4d4b-8e88-7af9041944b6@atsign00001:5ddc84dc-fc1b-4544-bfe7-d85ea195db4b

FINER|2023-05-25 15:11:16.504657|Monitor (@atsign00001)|Using AtChops to do the PKAM signing

INFO|2023-05-25 15:11:16.505855|Monitor (@atsign00001)|socket.listen onDone called. Will destroy socket, set status stopped, call retryCallback

FINER|2023-05-25 15:11:16.506163|NotificationServiceImpl (@atsign00001)|monitor retry for @atsign00001

INFO|2023-05-25 15:11:16.506569|Monitor (@atsign00001)|Monitor error Null check operator used on a null value - calling the retryCallback

INFO|2023-05-25 15:11:16.506775|NotificationServiceImpl (@atsign00001)|Monitor retry already queued

FINER|2023-05-25 15:11:21.851581|Monitor (@atsign00001)|RECEIVED data:_2e680e1c-e093-4040-aa15-3a5415161ba3@atsign00001:b8c1c596-c81e-4005-a142-c12b7924b4b6

FINER|2023-05-25 15:11:21.851847|Monitor (@atsign00001)|received response on monitor: data:_2e680e1c-e093-4040-aa15-3a5415161ba3@atsign00001:b8c1c596-c81e-4005-a142-c12b7924b4b6

FINER|2023-05-25 15:11:21.855320|Monitor (@atsign00001)|Authenticating the monitor connection: from result:_2e680e1c-e093-4040-aa15-3a5415161ba3@atsign00001:b8c1c596-c81e-4005-a142-c12b7924b4b6

FINER|2023-05-25 15:11:21.855655|Monitor (@atsign00001)|Using AtChops to do the PKAM signing

INFO|2023-05-25 15:11:21.856927|Monitor (@atsign00001)|socket.listen onDone called. Will destroy socket, set status stopped, call retryCallback

FINER|2023-05-25 15:11:21.857295|NotificationServiceImpl (@atsign00001)|monitor retry for @atsign00001

INFO|2023-05-25 15:11:21.857792|Monitor (@atsign00001)|Monitor error Null check operator used on a null value - calling the retryCallback

INFO|2023-05-25 15:11:21.858072|NotificationServiceImpl (@atsign00001)|Monitor retry already queued

Expected behavior

Screenshots

No response

Smartphones

Were you using an atApplication when the bug was found?

No response

Additional context

No response

murali-shris commented 1 year ago

When auth for sync is attempted,wrong signing algo is sent pkam:signingAlgo:rsa2048:hashingAlgo:sha256:NDRiN2Y5ZTE2M2Y4YjMyOGZkN2YwZDIzOGE0YmZiMDdiNGZjY2RhMTUxMzAwMmNkNWMyMjljNDY3YjQwYzNhNWM4NzgzYjc5NzU5N2E1NTdlNjkxMTA4MzRjYzkxYTNmOTAyNmRjNTlmMWNlMGJiOWJiMGM4YjZkZWFhNDA4M2E=

murali-shris commented 1 year ago

When auth for sync is attempted,wrong signing algo is sent pkam:signingAlgo:rsa2048:hashingAlgo:sha256:NDRiN2Y5ZTE2M2Y4YjMyOGZkN2YwZDIzOGE0YmZiMDdiNGZjY2RhMTUxMzAwMmNkNWMyMjljNDY3YjQwYzNhNWM4NzgzYjc5NzU5N2E1NTdlNjkxMTA4MzRjYzkxYTNmOTAyNmRjNTlmMWNlMGJiOWJiMGM4YjZkZWFhNDA4M2E=

Monitor was using deprecated at_chops.signString method which was using the default pkam signing and hashing algo. Fixed the issue by using at_chops.sign() method and setting the hashing and signing algo in at_client_preference.