Skip to content

Commit

Permalink
Fix command timeouts during commissioning. (#19137)
Browse files Browse the repository at this point in the history 
* Fix command timeouts during commissioning.

Several fixes here:

1. AutoCommissioner has a comment about how per spec everything during
   commissioning needs at least a 30s timeout, and it was passing that to
   PerformCommissioningStep, but DeviceCommissioner was ignoring the "timeout"
   parameter for a bunch of the cases, including crucially for AddNOC and
   CSRRequest.  Those can take a while to run, and were hitting the
   now-much-lower default 2s timeout.  The fix here is to stop ignoring the
   passed-in value.

2. The passed-in timeout value computation in AutoCommissioner was not quite
   right.  It was set to max(30s, network-connect-time), but the network connect
   time is the processing time on the server, not the total time including
   transport latency.  Fix the computation of the timeout to:
   a. Take the network connect times for the network enable steps, a "slow
      crypto" time of 15s for the AddNOC and CSRRequest steps, and the default
      IM timeout for all other steps and treat that as the server processing
      time.
   b. Add the transport timeout bits from our device's session to that server
      processing time.
   c. If the result is less than the spec-mandated 30s timeout, use 30s,
      otherwise use the result we computed.

3. Assuming that BLE has 0 transport latency is wrong.  Not clear what the right
   value is, but for now setting it to the same as TCP.

Fixes #19135

* Address review comments.

* Address review comment
  • Loading branch information
@bzbarsky-apple
bzbarsky-apple authored Jun 3, 2022
1 parent 847b0ba commit b27420a
Show file tree
Hide file tree
Showing 6 changed files with 94 additions and 38 deletions.
50 changes: 40 additions & 10 deletions src/controller/AutoCommissioner.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -18,6 +18,7 @@

#include <controller/AutoCommissioner.h>

#include <app/InteractionModelTimeout.h>
#include <controller/CHIPDeviceController.h>
#include <credentials/CHIPCert.h>
#include <lib/support/SafeInt.h>
Expand Down Expand Up @@ -288,29 +289,56 @@ CHIP_ERROR AutoCommissioner::StartCommissioning(DeviceCommissioner * commissione
CHIP_ERROR err = CHIP_NO_ERROR;
CommissioningStage nextStage = GetNextCommissioningStage(CommissioningStage::kSecurePairing, err);
mCommissioner->PerformCommissioningStep(mCommissioneeDeviceProxy, nextStage, mParams, this, GetEndpoint(nextStage),
GetCommandTimeout(nextStage));
GetCommandTimeout(mCommissioneeDeviceProxy, nextStage));
return CHIP_NO_ERROR;
}

Optional<System::Clock::Timeout> AutoCommissioner::GetCommandTimeout(CommissioningStage stage) const
Optional<System::Clock::Timeout> AutoCommissioner::GetCommandTimeout(DeviceProxy * device, CommissioningStage stage) const
{
// Per spec, all commands that are sent with the arm failsafe held need at least a 30s timeout.
// Network clusters can indicate the time required to connect, so if we are connecting, use that time as long as it is > 30s.
app::Clusters::NetworkCommissioning::Attributes::ConnectMaxTimeSeconds::TypeInfo::DecodableType seconds = 30;
// Network clusters can indicate the time required to connect, so if we are
// connecting, use that time as our "how long it takes to process server
// side" time. Otherwise pick a time that should be enough for the command
// processing: 7s for slow steps that can involve crypto, the default IM
// timeout otherwise.
// TODO: is this a reasonable estimate for the slow-crypto cases?
constexpr System::Clock::Timeout kSlowCryptoProcessingTime = System::Clock::Seconds16(7);

System::Clock::Timeout timeout;
switch (stage)
{
case CommissioningStage::kWiFiNetworkEnable:
ChipLogProgress(Controller, "Setting wifi connection time min = %u",
mDeviceCommissioningInfo.network.wifi.minConnectionTime);
seconds = std::max(mDeviceCommissioningInfo.network.wifi.minConnectionTime, seconds);
timeout = System::Clock::Seconds16(mDeviceCommissioningInfo.network.wifi.minConnectionTime);
break;
case CommissioningStage::kThreadNetworkEnable:
seconds = std::max(mDeviceCommissioningInfo.network.thread.minConnectionTime, seconds);
timeout = System::Clock::Seconds16(mDeviceCommissioningInfo.network.thread.minConnectionTime);
break;
case CommissioningStage::kSendNOC:
case CommissioningStage::kSendOpCertSigningRequest:
timeout = kSlowCryptoProcessingTime;
break;
default:
timeout = app::kExpectedIMProcessingTime;
break;
}
return MakeOptional(System::Clock::Timeout(System::Clock::Seconds16(seconds)));

// Adjust the timeout for our session transport latency, if we have access
// to a session.
auto sessionHandle = device->GetSecureSession();
if (sessionHandle.HasValue())
{
timeout = sessionHandle.Value()->ComputeRoundTripTimeout(timeout);
}

// Enforce the spec minimal timeout. Maybe this enforcement should live in
// the DeviceCommissioner?
if (timeout < kMinimumCommissioningStepTimeout)
{
timeout = kMinimumCommissioningStepTimeout;
}

return MakeOptional(timeout);
}

CHIP_ERROR AutoCommissioner::NOCChainGenerated(ByteSpan noc, ByteSpan icac, ByteSpan rcac, AesCcm128KeySpan ipk,
Expand All @@ -326,7 +354,8 @@ CHIP_ERROR AutoCommissioner::NOCChainGenerated(ByteSpan noc, ByteSpan icac, Byte
mParams.SetNoc(noCert);

CommissioningStage nextStage = CommissioningStage::kSendTrustedRootCert;
mCommissioner->PerformCommissioningStep(mCommissioneeDeviceProxy, nextStage, mParams, this, 0, GetCommandTimeout(nextStage));
mCommissioner->PerformCommissioningStep(mCommissioneeDeviceProxy, nextStage, mParams, this, 0,
GetCommandTimeout(mCommissioneeDeviceProxy, nextStage));

// Trusted root cert has been sent, so we can re-use the icac buffer for the icac.
if (!icac.empty())
Expand Down Expand Up @@ -476,7 +505,8 @@ CHIP_ERROR AutoCommissioner::CommissioningStepFinished(CHIP_ERROR err, Commissio
}

mParams.SetCompletionStatus(completionStatus);
mCommissioner->PerformCommissioningStep(proxy, nextStage, mParams, this, GetEndpoint(nextStage), GetCommandTimeout(nextStage));
mCommissioner->PerformCommissioningStep(proxy, nextStage, mParams, this, GetEndpoint(nextStage),
GetCommandTimeout(proxy, nextStage));
return CHIP_NO_ERROR;
}

Expand Down
6 changes: 5 additions & 1 deletion src/controller/AutoCommissioner.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -53,7 +53,11 @@ class AutoCommissioner : public CommissioningDelegate
ByteSpan GetPAI() const { return ByteSpan(mPAI, mPAILen); }

CHIP_ERROR NOCChainGenerated(ByteSpan noc, ByteSpan icac, ByteSpan rcac, AesCcm128KeySpan ipk, NodeId adminSubject);
Optional<System::Clock::Timeout> GetCommandTimeout(CommissioningStage stage) const;
/**
* The device argument to GetCommandTimeout is the device whose session will
* be used for sending the relevant command.
*/
Optional<System::Clock::Timeout> GetCommandTimeout(DeviceProxy * device, CommissioningStage stage) const;
EndpointId GetEndpoint(const CommissioningStage & stage) const;
CommissioningStage GetNextCommissioningStageInternal(CommissioningStage currentStage, CHIP_ERROR & lastErr);

Expand Down
49 changes: 29 additions & 20 deletions src/controller/CHIPDeviceController.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -812,7 +812,8 @@ void DeviceCommissioner::OnSessionEstablished(const SessionHandle & session)
}

CHIP_ERROR DeviceCommissioner::SendCertificateChainRequestCommand(DeviceProxy * device,
Credentials::CertificateType certificateType)
Credentials::CertificateType certificateType,
Optional<System::Clock::Timeout> timeout)
{
MATTER_TRACE_EVENT_SCOPE("SendCertificateChainRequestCommand", "DeviceCommissioner");
ChipLogDetail(Controller, "Sending Certificate Chain request to %p device", device);
Expand All @@ -821,7 +822,7 @@ CHIP_ERROR DeviceCommissioner::SendCertificateChainRequestCommand(DeviceProxy *
OperationalCredentials::Commands::CertificateChainRequest::Type request;
request.certificateType = certificateType;
return SendCommand<OperationalCredentialsCluster>(device, request, OnCertificateChainResponse,
OnCertificateChainFailureResponse);
OnCertificateChainFailureResponse, timeout);

return CHIP_NO_ERROR;
}
Expand All @@ -847,7 +848,8 @@ void DeviceCommissioner::OnCertificateChainResponse(
commissioner->CommissioningStageComplete(CHIP_NO_ERROR, report);
}

CHIP_ERROR DeviceCommissioner::SendAttestationRequestCommand(DeviceProxy * device, const ByteSpan & attestationNonce)
CHIP_ERROR DeviceCommissioner::SendAttestationRequestCommand(DeviceProxy * device, const ByteSpan & attestationNonce,
Optional<System::Clock::Timeout> timeout)
{
MATTER_TRACE_EVENT_SCOPE("SendAttestationRequestCommand", "DeviceCommissioner");
ChipLogDetail(Controller, "Sending Attestation request to %p device", device);
Expand All @@ -857,7 +859,7 @@ CHIP_ERROR DeviceCommissioner::SendAttestationRequestCommand(DeviceProxy * devic
request.attestationNonce = attestationNonce;

ReturnErrorOnFailure(
SendCommand<OperationalCredentialsCluster>(device, request, OnAttestationResponse, OnAttestationFailureResponse));
SendCommand<OperationalCredentialsCluster>(device, request, OnAttestationResponse, OnAttestationFailureResponse, timeout));
ChipLogDetail(Controller, "Sent Attestation request, waiting for the Attestation Information");
return CHIP_NO_ERROR;
}
Expand Down Expand Up @@ -979,8 +981,11 @@ void DeviceCommissioner::ExtendArmFailSafeForFailedDeviceAttestation(Attestation
request.expiryLengthSeconds = expiryLengthSeconds.Value();
request.breadcrumb = mCommissioningStage;
ChipLogProgress(Controller, "Changing fail-safe timer to %u seconds to handle DA failure", request.expiryLengthSeconds);
// Per spec, anything we do with the fail-safe armed must not time out
// in less than kMinimumCommissioningStepTimeout.
SendCommand<GeneralCommissioningCluster>(mDeviceBeingCommissioned, request, OnArmFailSafeExtendedForFailedDeviceAttestation,
OnFailedToExtendedArmFailSafeFailedDeviceAttestation);
OnFailedToExtendedArmFailSafeFailedDeviceAttestation,
MakeOptional(kMinimumCommissioningStepTimeout));
}
else
{
Expand Down Expand Up @@ -1023,7 +1028,8 @@ CHIP_ERROR DeviceCommissioner::ValidateCSR(DeviceProxy * proxy, const ByteSpan &
AttestationSignature, dacPubkey, csrNonce);
}

CHIP_ERROR DeviceCommissioner::SendOperationalCertificateSigningRequestCommand(DeviceProxy * device, const ByteSpan & csrNonce)
CHIP_ERROR DeviceCommissioner::SendOperationalCertificateSigningRequestCommand(DeviceProxy * device, const ByteSpan & csrNonce,
Optional<System::Clock::Timeout> timeout)
{
MATTER_TRACE_EVENT_SCOPE("SendOperationalCertificateSigningRequestCommand", "DeviceCommissioner");
ChipLogDetail(Controller, "Sending CSR request to %p device", device);
Expand All @@ -1032,8 +1038,8 @@ CHIP_ERROR DeviceCommissioner::SendOperationalCertificateSigningRequestCommand(D
OperationalCredentials::Commands::CSRRequest::Type request;
request.CSRNonce = csrNonce;

ReturnErrorOnFailure(
SendCommand<OperationalCredentialsCluster>(device, request, OnOperationalCertificateSigningRequest, OnCSRFailureResponse));
ReturnErrorOnFailure(SendCommand<OperationalCredentialsCluster>(device, request, OnOperationalCertificateSigningRequest,
OnCSRFailureResponse, timeout));
ChipLogDetail(Controller, "Sent CSR request, waiting for the CSR");
return CHIP_NO_ERROR;
}
Expand Down Expand Up @@ -1120,9 +1126,10 @@ CHIP_ERROR DeviceCommissioner::ProcessCSR(DeviceProxy * proxy, const ByteSpan &

CHIP_ERROR DeviceCommissioner::SendOperationalCertificate(DeviceProxy * device, const ByteSpan & nocCertBuf,
const Optional<ByteSpan> & icaCertBuf, const AesCcm128KeySpan ipk,
const NodeId adminSubject)
const NodeId adminSubject, Optional<System::Clock::Timeout> timeout)
{
MATTER_TRACE_EVENT_SCOPE("SendOperationalCertificate", "DeviceCommissioner");

VerifyOrReturnError(device != nullptr, CHIP_ERROR_INVALID_ARGUMENT);

OperationalCredentials::Commands::AddNOC::Type request;
Expand All @@ -1132,8 +1139,8 @@ CHIP_ERROR DeviceCommissioner::SendOperationalCertificate(DeviceProxy * device,
request.caseAdminSubject = adminSubject;
request.adminVendorId = mVendorId;

ReturnErrorOnFailure(
SendCommand<OperationalCredentialsCluster>(device, request, OnOperationalCertificateAddResponse, OnAddNOCFailureResponse));
ReturnErrorOnFailure(SendCommand<OperationalCredentialsCluster>(device, request, OnOperationalCertificateAddResponse,
OnAddNOCFailureResponse, timeout));

ChipLogProgress(Controller, "Sent operational certificate to the device");

Expand Down Expand Up @@ -1206,7 +1213,8 @@ void DeviceCommissioner::OnOperationalCertificateAddResponse(
}
}

CHIP_ERROR DeviceCommissioner::SendTrustedRootCertificate(DeviceProxy * device, const ByteSpan & rcac)
CHIP_ERROR DeviceCommissioner::SendTrustedRootCertificate(DeviceProxy * device, const ByteSpan & rcac,
Optional<System::Clock::Timeout> timeout)
{
MATTER_TRACE_EVENT_SCOPE("SendTrustedRootCertificate", "DeviceCommissioner");
VerifyOrReturnError(device != nullptr, CHIP_ERROR_INVALID_ARGUMENT);
Expand All @@ -1216,7 +1224,7 @@ CHIP_ERROR DeviceCommissioner::SendTrustedRootCertificate(DeviceProxy * device,
OperationalCredentials::Commands::AddTrustedRootCertificate::Type request;
request.rootCertificate = rcac;
ReturnErrorOnFailure(
SendCommand<OperationalCredentialsCluster>(device, request, OnRootCertSuccessResponse, OnRootCertFailureResponse));
SendCommand<OperationalCredentialsCluster>(device, request, OnRootCertSuccessResponse, OnRootCertFailureResponse, timeout));

ChipLogProgress(Controller, "Sent root certificate to the device");

Expand Down Expand Up @@ -1382,7 +1390,8 @@ void DeviceCommissioner::CleanupCommissioning(DeviceProxy * proxy, NodeId nodeId
ChipLogProgress(Controller, "Expiring failsafe on proxy %p", proxy);
mDeviceBeingCommissioned = proxy;
// We actually want to do the same thing on success or failure because we're already in a failure state
SendCommand<GeneralCommissioningCluster>(proxy, request, OnDisarmFailsafe, OnDisarmFailsafeFailure);
SendCommand<GeneralCommissioningCluster>(proxy, request, OnDisarmFailsafe, OnDisarmFailsafeFailure,
/* timeout = */ NullOptional);
}
}

Expand Down Expand Up @@ -1898,11 +1907,11 @@ void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, Commissio
break;
case CommissioningStage::kSendPAICertificateRequest:
ChipLogProgress(Controller, "Sending request for PAI certificate");
SendCertificateChainRequestCommand(proxy, CertificateType::kPAI);
SendCertificateChainRequestCommand(proxy, CertificateType::kPAI, timeout);
break;
case CommissioningStage::kSendDACCertificateRequest:
ChipLogProgress(Controller, "Sending request for DAC certificate");
SendCertificateChainRequestCommand(proxy, CertificateType::kDAC);
SendCertificateChainRequestCommand(proxy, CertificateType::kDAC, timeout);
break;
case CommissioningStage::kSendAttestationRequest:
ChipLogProgress(Controller, "Sending Attestation Request to the device.");
Expand All @@ -1912,7 +1921,7 @@ void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, Commissio
CommissioningStageComplete(CHIP_ERROR_INVALID_ARGUMENT);
return;
}
SendAttestationRequestCommand(proxy, params.GetAttestationNonce().Value());
SendAttestationRequestCommand(proxy, params.GetAttestationNonce().Value(), timeout);
break;
case CommissioningStage::kAttestationVerification: {
ChipLogProgress(Controller, "Verifying attestation");
Expand Down Expand Up @@ -1946,7 +1955,7 @@ void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, Commissio
CommissioningStageComplete(CHIP_ERROR_INVALID_ARGUMENT);
return;
}
SendOperationalCertificateSigningRequestCommand(proxy, params.GetCSRNonce().Value());
SendOperationalCertificateSigningRequestCommand(proxy, params.GetCSRNonce().Value(), timeout);
break;
case CommissioningStage::kValidateCSR: {
if (!params.GetNOCChainGenerationParameters().HasValue() || !params.GetDAC().HasValue() || !params.GetCSRNonce().HasValue())
Expand Down Expand Up @@ -1993,7 +2002,7 @@ void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, Commissio
CommissioningStageComplete(CHIP_ERROR_INVALID_ARGUMENT);
return;
}
CHIP_ERROR err = SendTrustedRootCertificate(proxy, params.GetRootCert().Value());
CHIP_ERROR err = SendTrustedRootCertificate(proxy, params.GetRootCert().Value(), timeout);
if (err != CHIP_NO_ERROR)
{
ChipLogError(Controller, "Error sending trusted root certificate: %s", err.AsString());
Expand Down Expand Up @@ -2023,7 +2032,7 @@ void DeviceCommissioner::PerformCommissioningStep(DeviceProxy * proxy, Commissio
return;
}
SendOperationalCertificate(proxy, params.GetNoc().Value(), params.GetIcac(), params.GetIpk().Value(),
params.GetAdminSubject().Value());
params.GetAdminSubject().Value(), timeout);
break;
case CommissioningStage::kWiFiNetworkSetup: {
if (!params.GetWiFiCredentials().HasValue())
Expand Down
17 changes: 10 additions & 7 deletions src/controller/CHIPDeviceController.h
View file
Original file line number Diff line number Diff line change
Expand Up @@ -619,24 +619,27 @@ class DLL_EXPORT DeviceCommissioner : public DeviceController,
/* This function sends a Device Attestation Certificate chain request to the device.
The function does not hold a reference to the device object.
*/
CHIP_ERROR SendCertificateChainRequestCommand(DeviceProxy * device, Credentials::CertificateType certificateType);
CHIP_ERROR SendCertificateChainRequestCommand(DeviceProxy * device, Credentials::CertificateType certificateType,
Optional<System::Clock::Timeout> timeout);
/* This function sends an Attestation request to the device.
The function does not hold a reference to the device object.
*/
CHIP_ERROR SendAttestationRequestCommand(DeviceProxy * device, const ByteSpan & attestationNonce);
CHIP_ERROR SendAttestationRequestCommand(DeviceProxy * device, const ByteSpan & attestationNonce,
Optional<System::Clock::Timeout> timeout);
/* This function sends an CSR request to the device.
The function does not hold a reference to the device object.
*/
CHIP_ERROR SendOperationalCertificateSigningRequestCommand(DeviceProxy * device, const ByteSpan & csrNonce);
CHIP_ERROR SendOperationalCertificateSigningRequestCommand(DeviceProxy * device, const ByteSpan & csrNonce,
Optional<System::Clock::Timeout> timeout);
/* This function sends the operational credentials to the device.
The function does not hold a reference to the device object.
*/
CHIP_ERROR SendOperationalCertificate(DeviceProxy * device, const ByteSpan & nocCertBuf, const Optional<ByteSpan> & icaCertBuf,
AesCcm128KeySpan ipk, NodeId adminSubject);
AesCcm128KeySpan ipk, NodeId adminSubject, Optional<System::Clock::Timeout> timeout);
/* This function sends the trusted root certificate to the device.
The function does not hold a reference to the device object.
*/
CHIP_ERROR SendTrustedRootCertificate(DeviceProxy * device, const ByteSpan & rcac);
CHIP_ERROR SendTrustedRootCertificate(DeviceProxy * device, const ByteSpan & rcac, Optional<System::Clock::Timeout> timeout);

/* This function is called by the commissioner code when the device completes
the operational credential provisioning process.
Expand Down Expand Up @@ -755,9 +758,9 @@ class DLL_EXPORT DeviceCommissioner : public DeviceController,
template <typename ClusterObjectT, typename RequestObjectT>
CHIP_ERROR SendCommand(DeviceProxy * device, const RequestObjectT & request,
CommandResponseSuccessCallback<typename RequestObjectT::ResponseType> successCb,
CommandResponseFailureCallback failureCb)
CommandResponseFailureCallback failureCb, Optional<System::Clock::Timeout> timeout)
{
return SendCommand<ClusterObjectT>(device, request, successCb, failureCb, 0, NullOptional);
return SendCommand<ClusterObjectT>(device, request, successCb, failureCb, 0, timeout);
}

template <typename ClusterObjectT, typename RequestObjectT>
Expand Down
Loading

0 comments on commit b27420a

Please sign in to comment.