Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

crypto: logging updates for verification #3949

Merged
merged 7 commits into from
Sep 5, 2024
Merged

crypto: logging updates for verification #3949

merged 7 commits into from
Sep 5, 2024

Conversation

richvdh
Copy link
Member

@richvdh richvdh commented Sep 4, 2024

A collection of random logging updates, that would have made my life easier when trying to debug a verification failure this week.

Copy link

codecov bot commented Sep 4, 2024

Codecov Report

Attention: Patch coverage is 90.90909% with 2 lines in your changes missing coverage. Please review.

Project coverage is 84.17%. Comparing base (f7ee643) to head (f6429e4).
Report is 10 commits behind head on main.

Files with missing lines Patch % Lines
...tes/matrix-sdk-crypto/src/verification/requests.rs 33.33% 2 Missing ⚠️
Additional details and impacted files
@@            Coverage Diff             @@
##             main    #3949      +/-   ##
==========================================
- Coverage   84.18%   84.17%   -0.01%     
==========================================
  Files         267      267              
  Lines       28181    28196      +15     
==========================================
+ Hits        23723    23734      +11     
- Misses       4458     4462       +4     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

@richvdh richvdh marked this pull request as ready for review September 4, 2024 22:42
@richvdh richvdh requested review from a team as code owners September 4, 2024 22:42
@richvdh richvdh requested review from bnjbvr and BillCarsonFr and removed request for a team September 4, 2024 22:42
Copy link
Member

@bnjbvr bnjbvr left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm worried that there are many high level log statements (info/debug), but if these are for events that don't happen that often I'm fine with the changes.

Still needs a review from some crypto folks to validate this is safe to publish this data.

@@ -126,6 +126,24 @@ impl CryptoStoreWrapper {

self.store.save_changes(changes).await?;

// If we updated our own public identity, log it for debugging purposes
for updated_identity in
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can you wrap the loop in a if tracing::level_enabled!(tracing::level::Debug)?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@@ -105,11 +105,21 @@ impl VerificationCache {

#[cfg(feature = "qrcode")]
pub fn insert_qr(&self, qr: QrVerification) {
tracing::debug!(
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: don't use a fully qualified path but instead use tracing::debug at the top.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@@ -634,9 +634,10 @@ impl IdentitiesBeingVerified {
if verified_identities.is_some_and(|i| {
i.iter().any(|verified| verified.user_id() == identity.user_id())
}) {
trace!(
info!(
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does this have to be an info! level? I suppose it's fine because it shouldn't happen that often?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it's kinda important -- about the same as other stuff that is logged at info -- and it should only happen once per verification.

@@ -328,6 +328,7 @@ impl QrVerification {

/// Confirm that the other side has scanned our QR code.
pub fn confirm_scanning(&self) -> Option<OutgoingVerificationRequest> {
info!("User confirmed other side scanned our QR code");
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can this be a debug or trace instead? Otherwise the verification will cause many many info-level statements

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah will make this one debug.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@richvdh
Copy link
Member Author

richvdh commented Sep 5, 2024

I'm worried that there are many high level log statements (info/debug), but if these are for events that don't happen that often I'm fine with the changes.

Yes, these should be pretty rare: either a one-off at startup, or in response to a user-interactive verification, which itself happens very rarely.

Copy link
Contributor

@andybalaam andybalaam left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

All the additional crypto content logged is part of a user's public identity so OK to log.

);
}
}

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

From a DM with Rich:

Andy: You state here that these are all part of our public identity

Rich:

identities.new and identities.changed are both Vec. UserIdentityData::own is Option, which is:

pub struct OwnUserIdentityData {
    user_id: OwnedUserId,
    master_key: Arc<MasterPubkey>,
    self_signing_key: Arc<SelfSigningPubkey>,
    user_signing_key: Arc<UserSigningPubkey>,
    #[serde(deserialize_with = "deserialize_own_user_identity_data_verified")]
    verified: Arc<RwLock<OwnUserIdentityVerifiedState>>,
}

... and note the keys in there are all PubKey.

This convinced me :-)

@andybalaam andybalaam removed the request for review from BillCarsonFr September 5, 2024 10:46
For debugging, it's useful to have a record of what we believe our own public
cross-signing keys to be. Currently, we log the keys at startup if we restore
them from the database, but if we subsequently create, or download, a set of
keys, they aren't logged.
Take the logging that happens when a QR code verification is added to the
`verification cache`, and push it down to the `VerificationCache` itself. Doing
so means that we will log when we *show* a QR code as well as when we scan it.

I would have found this helpful when trying to debug a verification flow this
week.
Attach the flow_id (the transaction ID or message ID from the `request`
message) to the span, so that it is displayed alongside loglines that happen
when processing the request.
This is the message that tells us whether the other side wants to do QR code or
SAS (emoji) verification. Knowing which they have chosen is really helpful for
following the flow!
 * Upgrade the log when we get the "reciprocate" message (which tells us the
   other side has scanned our QR code) to debug, instead of trace.
 * Warn if we get a reciprocate we don't understand
 * Log when the user confirms that the other side has scanned successfully.
* Not verifying the remote device/user is normal: log it at debug rather than
  info.
* On the other hand, if we do verify something, let's log that at info rather
  than trace.

Also fix a comment, while we're here.
// If we updated our own public identity, log it for debugging purposes
if tracing::level_enabled!(tracing::Level::DEBUG) {
for updated_identity in
identities.new.iter().chain(identities.changed.iter()).filter_map(|id| id.own())
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Took me sometime to see why this was just own identity. I sort of expected a have a filter on user_id() == but I guess it's fine

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I sort of expected a have a filter on user_id() == but I guess it's fine

well, that's what filter_map(|id| id.own()) is doing. If we filtered on user_id() we'd still need id.own() but we'd also have to unwrap() it or something.

@@ -33,6 +34,14 @@ impl SelfSigningPubkey {
&self.0.usage
}

/// Get the first available self signing key.
Copy link
Member

@BillCarsonFr BillCarsonFr Sep 5, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This comment is a bit strange. The first available? It's just getting the ed25519 key and there is only one -if the json is valid as per spec?-

Required: The public key. The object must have exactly one property, whose name is in the form algorithm:unpadded_base64_public_key, and whose value is the unpadded base64 public key.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Well, the line just below does explain that there is probably only one key.

Honestly I'm not a big fan of this API either, but it's just cargo-culted from the MasterPubkey implementation.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It's still a list in the spec. You could change this and reject things at deserialization that don't adhere to this rule, but that's a topic for another PR.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You could change this and reject things at deserialization that don't adhere to this rule, but that's a topic for another PR.

yeah, exactly that.

Copy link
Member

@BillCarsonFr BillCarsonFr left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Just minor nits, approved

@richvdh richvdh merged commit 3204953 into main Sep 5, 2024
40 checks passed
@richvdh richvdh deleted the rav/logging_work branch September 5, 2024 12:22
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants