Use debug level logging to avoid performance impact (line#23) (line#24)

rpserver/src/main/java/com/linecorp/line/auth/fido/fido2/rpserver/controller/AdapterController.java

@@ -78,8 +78,8 @@ public void prepareUri() {
 
  fidoServerHost = fidoServerConfig.getHost();
  scheme = fidoServerConfig.getScheme();
- log.info("fidoServerHost: " + fidoServerHost);
- log.info("scheme: " + scheme);
+ log.debug("fidoServerHost: {}", fidoServerHost);
+ log.debug("scheme: {}", scheme);
 
  regChallengeUri = uriComponentsBuilder
  .scheme(scheme)

rpserver/src/main/java/com/linecorp/line/auth/fido/fido2/rpserver/controller/CredentialController.java

@@ -62,8 +62,8 @@ public void prepareUri() {
  fidoServerHost = fidoServerConfig.getHost();
  scheme = fidoServerConfig.getScheme();
 
- log.info("fidoServerHost: " + fidoServerHost);
- log.info("scheme: " + scheme);
+ log.debug("fidoServerHost: {}", fidoServerHost);
+ log.debug("scheme: {}", scheme);
 
  getDeleteCredentialsUri = uriComponentsBuilder
  .scheme(scheme)

server/src/main/java/com/linecorp/line/auth/fido/fido2/server/attestation/apple/AppleAnonymousAttestationVerifier.java

@@ -58,7 +58,7 @@ public AttestationStatementFormatIdentifier getIdentifier() {
  public AttestationVerificationResult verify(AttestationStatement attestationStatement, AuthenticatorData authenticatorData, byte[] clientDataHash) {
  AppleAnonymousAttestationStatement appleAnonymous = (AppleAnonymousAttestationStatement) attestationStatement;
 
- log.info("Prepare nonceToHash");
+ log.debug("Prepare nonceToHash");
  byte[] expectedNonceToHash = ByteBuffer
  .allocate(authenticatorData.getBytes().length + clientDataHash.length)
  .put(authenticatorData.getBytes())

server/src/main/java/com/linecorp/line/auth/fido/fido2/server/attestation/packed/PackedAttestationVerifier.java

@@ -82,20 +82,22 @@ public AttestationVerificationResult verify(AttestationStatement attestationStat
  throw new FIDO2ServerRuntimeException(InternalErrorCode.INVALID_COSE_ALGORITHM, "Alg " + packed.getAlg());
  }
 
- log.info("Prepare toBeSignedMessage");
+ log.debug("Prepare toBeSignedMessage");
  byte[] toBeSignedMessage = ByteBuffer
  .allocate(authenticatorData.getBytes().length + clientDataHash.length)
  .put(authenticatorData.getBytes())
  .put(clientDataHash)
  .array();
- log.debug("toBeSignedMessage (b64url enc): {}", Base64.getUrlEncoder().withoutPadding().encodeToString(toBeSignedMessage));
+ String base64UrlEncodedMessageBytes = Base64.getUrlEncoder().withoutPadding().encodeToString(toBeSignedMessage);
+ log.debug("toBeSignedMessage (b64url enc): {}", base64UrlEncodedMessageBytes);
 
  // attestation type
  // basic
+ String base64UrlEncodedSignature = Base64.getUrlEncoder().withoutPadding().encodeToString(packed.getSig());
  if (packed.getX5c() != null &&
  !packed.getX5c().isEmpty()) {
- log.info("Basic Attestation Type");
- log.info("Generate certificate list with x5c");
+ log.debug("Basic Attestation Type");
+ log.debug("Generate certificate list with x5c");
  List<Certificate> certificateList;
  try {
  certificateList = CertificateUtil.getCertificates(packed.getX5c());
@@ -106,10 +108,11 @@ public AttestationVerificationResult verify(AttestationStatement attestationStat
  PublicKey publicKey = certificateList.get(0).getPublicKey();
 
  // verify signature /w public key, toBeSignedMessage, signature, algorithm
- log.info("Verify signature /w public key in leaf cert {}, toBeSignedMessage {}, signature {}, algorithm {}",
+ log.debug("Verify signature /w public key in leaf cert {}, toBeSignedMessage {}, signature {}, algorithm {}",
  Base64.getUrlEncoder().withoutPadding().encodeToString(publicKey.getEncoded()),
- Base64.getUrlEncoder().withoutPadding().encodeToString(toBeSignedMessage),
- Base64.getUrlEncoder().withoutPadding().encodeToString(packed.getSig()), algorithm);
+ base64UrlEncodedMessageBytes,
+ base64UrlEncodedSignature,
+ algorithm);
  boolean result = SignatureHelper.verifySignature(publicKey, toBeSignedMessage, packed.getSig(), algorithm);
 
  X509Certificate certificate = (X509Certificate) certificateList.get(0);
@@ -129,10 +132,10 @@ public AttestationVerificationResult verify(AttestationStatement attestationStat
  .format(AttestationStatementFormatIdentifier.PACKED)
  .build();
  } else { // self
- log.info("Self Attestation Type");
+ log.debug("Self Attestation Type");
  CredentialPublicKey credentialPublicKey = authenticatorData.getAttestedCredentialData().getCredentialPublicKey();
 
- log.info("Get credential public key for verifying signature");
+ log.debug("Get credential public key for verifying signature");
  PublicKey publicKey;
  if (algorithm.isRSAAlgorithm()) {
  if (credentialPublicKey instanceof RSAKey) {
@@ -200,10 +203,11 @@ public AttestationVerificationResult verify(AttestationStatement attestationStat
  }
 
  // verify signature /w public key, toBeSignedMessage, signature, algorithm
- log.info("Verify signature /w credential public key {}, toBeSignedMessage {}, signature {}, algorithm {}",
+ log.debug("Verify signature /w credential public key {}, toBeSignedMessage {}, signature {}, algorithm {}",
  Base64.getUrlEncoder().withoutPadding().encodeToString(publicKey.getEncoded()),
- Base64.getUrlEncoder().withoutPadding().encodeToString(toBeSignedMessage),
- Base64.getUrlEncoder().withoutPadding().encodeToString(packed.getSig()), algorithm);
+ base64UrlEncodedMessageBytes,
+ base64UrlEncodedSignature,
+ algorithm);
  boolean result = SignatureHelper.verifySignature(publicKey, toBeSignedMessage, packed.getSig(), algorithm);
 
  return AttestationVerificationResult

server/src/main/java/com/linecorp/line/auth/fido/fido2/server/attestation/tpm/TpmAttestationVerifier.java

@@ -235,8 +235,7 @@ private void verifyTpmAikCert(X509Certificate aikCert) {
  final String OID_TCG_AT_TPM_MODEL = "2.23.133.2.2";
  final String OID_TCG_AT_TPM_VERSION = "2.23.133.2.3";
 
- log.info("AIK Cert Information");
- log.info(aikCert.toString());
+ log.debug("AIK Cert Information: {}", aikCert);
 
  try {
  // check version (MUST be set to 3)
@@ -291,7 +290,7 @@ private void verifyTpmAikCert(X509Certificate aikCert) {
  }
 
  TpmSubjectAlternativeName alternativeName = builder.build();
- log.info("TPM Subject Alternative name: {}", alternativeName);
+ log.debug("TPM Subject Alternative name: {}", alternativeName);
 
  // check extended key usage extension (MUST contain tcg-kp-AIKCertificate oid)
  List<String> extendedKeyUsage = aikCert.getExtendedKeyUsage();
@@ -308,17 +307,17 @@ private void verifyTpmAikCert(X509Certificate aikCert) {
  byte[] authInfoAccessExtensionValue = aikCert.getExtensionValue(
  Extension.authorityInfoAccess.getId());
 
- log.info("AIA extension info (Optional)");
+ log.debug("AIA extension info (Optional)");
  AccessDescription[] accessDescriptions = getAccessDescriptions(authInfoAccessExtensionValue);
  if (accessDescriptions != null) {
  for (AccessDescription accessDescription : accessDescriptions) {
 
  if (accessDescription.getAccessMethod().equals(OCSP_ACCESS_METHOD)) {
- log.info("AIA: OCSP enabled");
+ log.debug("AIA: OCSP enabled");
  }
 
  if (accessDescription.getAccessMethod().equals(CRL_ACCESS_METHOD)) {
- log.info("AIA: CRL enabled");
+ log.debug("AIA: CRL enabled");
  }
 
  GeneralName gn = accessDescription.getAccessLocation();
@@ -327,7 +326,7 @@ private void verifyTpmAikCert(X509Certificate aikCert) {
  }
 
  DERIA5String str = (DERIA5String) ((DERTaggedObject) gn.toASN1Primitive()).getObject();
- log.info("Access Location: {}", str.getString());
+ log.debug("Access Location: {}", str);
  }
  }
 

server/src/main/java/com/linecorp/line/auth/fido/fido2/server/helper/ExtensionHelper.java

@@ -24,24 +24,20 @@
 @Slf4j
 public class ExtensionHelper {
  public static UserKey createUserKeyWithExtensions(UserKey.UserKeyBuilder userKeyBuilder, AuthenticationExtensionsClientOutputs clientExtensions, AuthenticatorExtension authenticatorExtensions) {
- // verify extension
- log.info("Verify extension");
-
- // check authenticator extensions
- log.info("Check authenticator extension");
+ log.debug("Check authenticator extension");
 
  if (authenticatorExtensions != null) {
  log.debug("Extensions: {}", authenticatorExtensions);
  if (authenticatorExtensions.getCredProtect() != null) {
- log.info("Handle credProtect extension");
+ log.debug("Handle credProtect extension");
  userKeyBuilder.credProtect(authenticatorExtensions.getCredProtect().getValue());
  }
  }
 
  // check client extensions
- log.info("Check client extension");
+ log.debug("Check client extension");
  if (clientExtensions != null) {
- log.info("Client extension output: {}", clientExtensions);
+ log.debug("Client extension output: {}", clientExtensions);
  if (clientExtensions.getCredProps() != null) {
  userKeyBuilder.rk(clientExtensions.getCredProps().getRk());
  }

server/src/main/java/com/linecorp/line/auth/fido/fido2/server/model/AuthenticatorData.java

@@ -122,7 +122,7 @@ protected static AuthenticatorData decodeAuthenticatorDataCommon(byte[] encoded,
  }
 
  protected static AuthenticatorExtension decodeAuthenticatorDataExtension(ByteArrayInputStream inputStream) throws IOException {
- log.info("Extension is included");
+ log.debug("Extension is included");
  int extensionDataLength = inputStream.available();
  if (extensionDataLength > 0) {
  byte[] extensionsBytes = new byte[extensionDataLength];

server/src/main/java/com/linecorp/line/auth/fido/fido2/server/service/AttestationServiceImpl.java

@@ -77,12 +77,12 @@ public AttestationServiceImpl(MetadataService metadataService, VendorSpecificMet
  @Override
  public AttestationVerificationResult verifyAttestation(byte[] clientDataHsh, AttestationObject attestationObject) {
  // verify attStmt
- log.info("Verify attStmt with format {}", attestationObject.getFmt());
+ log.debug("Verify attStmt with format {}", attestationObject.getFmt());
  AttestationVerificationResult attestationVerificationResult =
  attestationVerifierFactory
  .getVerifier(attestationObject.getFmt())
  .verify(attestationObject.getAttStmt(), attestationObject.getAuthData(), clientDataHsh);
- log.info("Attestation verification result {}", attestationVerificationResult);
+ log.debug("Attestation verification result {}", attestationVerificationResult);
  return attestationVerificationResult;
  }
 
@@ -93,7 +93,7 @@ public AttestationObject getAttestationObject(ServerAuthenticatorAttestationResp
  .decode(attestationResponse.getAttestationObject());
 
  // perform CBOR decoding
- log.info("Perform CBOR decoding of attestationObject");
+ log.debug("Perform CBOR decoding of attestationObject");
  CBORFactory cborFactory = new CBORFactory();
  ObjectMapper objectMapper = new ObjectMapper(cborFactory);
  AttestationObject attestationObject;
@@ -114,21 +114,21 @@ public void attestationObjectValidationCheck(String rpId, AuthenticatorSelection
  }
 
  // verify RP ID (compare with SHA256 hash or RP ID)
- log.info("Verify hash of RP ID with rpIdHash in authData");
+ log.debug("Verify hash of RP ID with rpIdHash in authData");
  byte[] rpIdHash = Digests.sha256(rpId.getBytes(StandardCharsets.UTF_8));
  if (!Arrays.equals(attestationObject.getAuthData().getRpIdHash(), rpIdHash)) {
  throw new FIDO2ServerRuntimeException(InternalErrorCode.RPID_HASH_NOT_MATCHED, "RP ID hash is not matched", AaguidUtil.convert(attestationObject.getAuthData().getAttestedCredentialData().getAaguid()));
  }
 
  // verify user present flag
- log.info("Verify user present flag. Should be set");
+ log.debug("Verify user present flag. Should be set");
  if (!attestationObject.getAuthData().isUserPresent()) {
  // Temporary comment out for Android chrome testings
 // throw new FIDO2ServerRuntimeException(InternalErrorCode.USER_PRESENCE_FLAG_NOT_SET);
  }
 
  // verify user verification
- log.info("Verify user verification flag if user verification required");
+ log.debug("Verify user verification flag if user verification required");
  if (authenticatorSelection != null &&
  authenticatorSelection.getUserVerification() != null &&
  authenticatorSelection.getUserVerification() == UserVerificationRequirement.REQUIRED &&
@@ -142,7 +142,7 @@ public void verifyAttestationCertificate(AttestationObject attestationObject, At
  // verify trustworthiness
  // check the attestation certificate chained up to root certificates
  // if fails, SHOULD reject the registration
- log.info("Verify trustworthiness of chain");
+ log.debug("Verify trustworthiness of chain");
 
  byte[] aaguid = attestationObject.getAuthData().getAttestedCredentialData().getAaguid();
  MetadataStatement metadataStatement = null;
@@ -202,9 +202,9 @@ private void verifyCertificateChainOfTrust(AttestationObject attestationObject,
 
  boolean result = CertPathUtil.validate(attestationVerificationResult.getTrustPath(),
  trustAnchors, enableRevocation);
- log.debug("trust path: " + attestationVerificationResult.getTrustPath());
- log.debug("trust anchors: " + trustAnchors);
- log.debug("validation result: " + result);
+ log.debug("trust path: {}", attestationVerificationResult.getTrustPath());
+ log.debug("trust anchors: {}", trustAnchors);
+ log.debug("validation result: {}", result);
 
  if (!result) {
  throw new FIDO2ServerRuntimeException(InternalErrorCode.CERTIFICATE_PATH_VALIDATION_FAIL);
@@ -217,20 +217,19 @@ private void verifyCertificateChainOfTrust(AttestationObject attestationObject,
  }
 
  private boolean hasCRLDistPointForRevokeCheck(AttestationVerificationResult attestationVerificationResult) throws IOException {
- log.debug("num certs in chain:" + attestationVerificationResult.getTrustPath().size());
+ log.debug("num certs in chain: {}", attestationVerificationResult.getTrustPath().size());
  X509Certificate leafCert = (X509Certificate) attestationVerificationResult.getTrustPath().get(0);
- log.debug("**** leaf cert subject: " + leafCert.getSubjectDN());
- log.debug("**** leaf cert issuer: " + leafCert.getIssuerDN());
+ log.debug("**** leaf cert subject: {}", leafCert.getSubjectDN());
+ log.debug("**** leaf cert issuer: {}", leafCert.getIssuerDN());
 
  byte[] cdpExt = leafCert.getExtensionValue(Extension.cRLDistributionPoints.getId());
  CRLDistPoint cdp = null;
  if (cdpExt != null) {
  cdp = CRLDistPoint.getInstance(X509ExtensionUtil.fromExtensionValue(cdpExt));
  }
- log.debug(String.format("***** SubjectDN: [%s], CDP: [%s]", leafCert.getSubjectDN(),
- cdp == null ? "<null>" : cdp));
+ log.debug("***** SubjectDN: [{}], CDP: [{}]", leafCert.getSubjectDN(), cdp);
  boolean enableRevocation = cdpExt != null;
- log.debug("enable revocation: " + enableRevocation);
+ log.debug("enable revocation: {}", enableRevocation);
  return enableRevocation;
  }
 

server/src/main/java/com/linecorp/line/auth/fido/fido2/server/service/ChallengeServiceImpl.java

@@ -142,8 +142,7 @@ public RegOptionResponse getRegChallenge(RegOptionRequest regOptionRequest) {
  // write session
  sessionService.createSession(session);
 
- log.debug("regOptionResponse: ");
- log.debug(regOptionResponse.toString());
+ log.debug("regOptionResponse: {}", regOptionResponse);
 
  return regOptionResponse;
  }
@@ -214,8 +213,7 @@ public AuthOptionResponse getAuthChallenge(AuthOptionRequest authOptionRequest)
  // write session
  sessionService.createSession(session);
 
- log.debug("authOptionResponse:");
- log.debug(authOptionResponse.toString());
+ log.debug("authOptionResponse: {}", authOptionResponse);
 
  return authOptionResponse;
  }

server/src/main/java/com/linecorp/line/auth/fido/fido2/server/service/ResponseCommonService.java

@@ -52,7 +52,7 @@ abstract public class ResponseCommonService {
  */
  public byte[] handleCommon(String type, String challengeSent, String base64UrlEncodedClientDataJSON, String origin, TokenBinding tokenBinding) {
  String clientDataJSON = new String(Base64.getUrlDecoder().decode(base64UrlEncodedClientDataJSON));
- log.info("clientDataJSON: {}", clientDataJSON);
+ log.debug("clientDataJSON: {}", clientDataJSON);
  CollectedClientData collectedClientData;
  try {
  collectedClientData = getCollectedClientData(clientDataJSON);
@@ -61,7 +61,7 @@ public byte[] handleCommon(String type, String challengeSent, String base64UrlEn
  }
  byte[] clientDataJSONBytes = clientDataJSON.getBytes();
 
- log.info("collectedClientData: {}", collectedClientData);
+ log.debug("collectedClientData: {}", collectedClientData);
  // verify collected client data
  if (StringUtils.isEmpty(collectedClientData.getType()) ||
  StringUtils.isEmpty(collectedClientData.getChallenge()) ||
@@ -70,19 +70,19 @@ public byte[] handleCommon(String type, String challengeSent, String base64UrlEn
  }
 
  // verify challenge (should be matched to challenge sent in create call)
- log.info("Verify challenge matched to challenge sent");
+ log.debug("Verify challenge matched to challenge sent");
  if (!collectedClientData.getChallenge().equals(challengeSent)) {
  throw new FIDO2ServerRuntimeException(InternalErrorCode.CHALLENGE_NOT_MATCHED);
  }
 
  // verify type
- log.info("Check operation type in collectedClientData");
+ log.debug("Check operation type in collectedClientData");
  if (!type.equals(collectedClientData.getType())) {
  throw new FIDO2ServerRuntimeException(InternalErrorCode.INVALID_OPERATION_TYPE);
  }
 
  // verify origin
- log.info("Verify origin matched to origin in collectedClientData");
+ log.debug("Verify origin matched to origin in collectedClientData");
  URI originFromClientData;
  URI originFromRp;
  try {
@@ -95,7 +95,7 @@ public byte[] handleCommon(String type, String challengeSent, String base64UrlEn
  checkOrigin(originFromClientData, originFromRp);
 
  // verify token binding
- log.info("Verify token binding if supported");
+ log.debug("Verify token binding if supported");
  if (collectedClientData.getTokenBinding() != null) {
  if (collectedClientData.getTokenBinding().getStatus() == null) {
  throw new FIDO2ServerRuntimeException(InternalErrorCode.TOKEN_BINDING_STATUS_MISSING);
@@ -117,7 +117,7 @@ public byte[] handleCommon(String type, String challengeSent, String base64UrlEn
  }
 
  // compute hash of clientDataJSON
- log.info("Compute hash of clientDataJSON");
+ log.debug("Compute hash of clientDataJSON");
 
  return Digests.sha256(clientDataJSONBytes);
  }