Improve debug messages for EMV and TAL

* The EMV layer should emit debug messages to indicate the high level
  transaction flow regardless of whether emv-tool already prints its
  own
* Use info messages for READ RECORD responses in TAL, which reverts the
  previous decision that that was too verbose

Author: leonlynch

src/emv.c

@@ -359,7 +359,7 @@ int emv_build_candidate_list(
 		return EMV_ERROR_INVALID_PARAMETER;
 	}
 
-	emv_debug_info("SELECT Payment System Environment (PSE)");
+	emv_debug_info("Select Payment System Environment (PSE)");
 	r = emv_tal_read_pse(ctx->ttl, &ctx->supported_aids, app_list);
 	if (r < 0) {
 		emv_debug_trace_msg("emv_tal_read_pse() failed; r=%d", r);
@@ -439,6 +439,7 @@ int emv_select_application(
 		ctx->selected_app = NULL;
 	}
 
+	emv_debug_info("Select application index #%u", index);
 	current_app = emv_app_list_remove_index(app_list, index);
 	if (!current_app) {
 		emv_debug_trace_msg("emv_app_list_remove_index() failed; index=%u", index);
@@ -521,6 +522,8 @@ int emv_initiate_application_processing(
 		return EMV_ERROR_INVALID_PARAMETER;
 	}
 
+	emv_debug_info("Initiate application processing");
+
 	// Clear existing ICC data and terminal data lists to avoid ambiguity
 	emv_tlv_list_clear(&ctx->icc);
 	emv_tlv_list_clear(&ctx->terminal);
@@ -803,6 +806,8 @@ int emv_read_application_data(struct emv_ctx_t* ctx)
 		return EMV_ERROR_INVALID_PARAMETER;
 	}
 
+	emv_debug_info("Read application data");
+
 	// Application File Locator (AFL) is required to read application records
 	if (!ctx->afl) {
 		// AFL not found; terminate session
@@ -842,7 +847,7 @@ int emv_read_application_data(struct emv_ctx_t* ctx)
 	if (r) {
 		emv_debug_trace_msg("emv_tal_read_afl_records() failed; r=%d", r);
 		if (r < 0) {
-			emv_debug_error("Error reading application data");
+			emv_debug_error("Error while reading application data");
 			if (r == EMV_TAL_ERROR_INTERNAL || r == EMV_TAL_ERROR_INVALID_PARAMETER) {
 				r = EMV_ERROR_INTERNAL;
 			} else {
@@ -851,7 +856,7 @@ int emv_read_application_data(struct emv_ctx_t* ctx)
 			goto error;
 		}
 		if (r != EMV_TAL_RESULT_ODA_RECORD_INVALID) {
-			emv_debug_error("Failed to read application data");
+			emv_debug_error("Failure while reading application data");
 			r = EMV_OUTCOME_CARD_ERROR;
 			goto error;
 		}
@@ -924,6 +929,8 @@ int emv_offline_data_authentication(struct emv_ctx_t* ctx)
 		return EMV_ERROR_INVALID_PARAMETER;
 	}
 
+	emv_debug_info("Offline data authentication");
+
 	// Ensure mandatory configuration fields are present and have valid length
 	term_caps = emv_tlv_list_find_const(&ctx->config, EMV_TAG_9F33_TERMINAL_CAPABILITIES);
 	if (!term_caps || term_caps->length != 3) {
@@ -1000,6 +1007,8 @@ int emv_processing_restrictions(struct emv_ctx_t* ctx)
 		return EMV_ERROR_INVALID_PARAMETER;
 	}
 
+	emv_debug_info("Processing restrictions");
+
 	// Ensure mandatory configuration fields are present and have valid length
 	term_app_version = emv_tlv_list_find_const(&ctx->config, EMV_TAG_9F09_APPLICATION_VERSION_NUMBER_TERMINAL);
 	if (!term_app_version || term_app_version->length != 2) {
@@ -1230,6 +1239,8 @@ int emv_terminal_risk_management(struct emv_ctx_t* ctx,
 		return EMV_ERROR_INVALID_PARAMETER;
 	}
 
+	emv_debug_info("Terminal risk management");
+
 	// Ensure mandatory configuration fields are present and have valid length
 	term_floor_limit = emv_tlv_list_find_const(&ctx->config, EMV_TAG_9F1B_TERMINAL_FLOOR_LIMIT);
 	if (!term_floor_limit || term_floor_limit->length != 4) {
@@ -1569,6 +1580,8 @@ int emv_card_action_analysis(struct emv_ctx_t* ctx)
 		return EMV_ODA_ERROR_INVALID_PARAMETER;
 	}
 
+	emv_debug_info("Card action analysis");
+
 	// Always decline offline for now until Terminal Action Analysis is fully
 	// implemented
 	ref_ctrl = EMV_TTL_GENAC_TYPE_AAC;

src/emv_tal.c

@@ -920,7 +920,7 @@ static int emv_tal_read_sfi_records(
 				return EMV_TAL_ERROR_READ_RECORD_PARSE_FAILED;
 			}
 		}
-		emv_debug_trace_ber("READ RECORD from SFI %u, record %u", record, record_len, afl_entry->sfi, record_number);
+		emv_debug_info_ber("READ RECORD [%u,%u] response", record, record_len, afl_entry->sfi, record_number);
 
 		r = emv_tlv_list_append(list, &record_list);
 		if (r) {