From 8f6099ac510526d89be50309dbeb52f62bbaa7d1 Mon Sep 17 00:00:00 2001 From: "Neal H. Walfield" Date: Mon, 16 Nov 2015 20:55:34 +0100 Subject: [PATCH] gpg: Add some debugging output. -- Signed-off-by: Neal H. Walfield --- g10/gpg.c | 12 ++++++++ g10/keydb.c | 22 ++++++++++++++- g10/keyring.c | 76 +++++++++++++++++++++++++++++++++++++++++++++++---- 3 files changed, 104 insertions(+), 6 deletions(-) diff --git a/g10/gpg.c b/g10/gpg.c index 0cc7038fa..5ba3a205c 100644 --- a/g10/gpg.c +++ b/g10/gpg.c @@ -2124,6 +2124,12 @@ check_user_ids (strlist_t *sp, default: log_bug ("Unsupport option: %d\n", t->flags >> 2); } + if (DBG_LOOKUP) + { + log_debug ("\n"); + log_debug ("%s: Checking %s=%s\n", __func__, option, t->d); + } + err = classify_user_id (t->d, &desc, 1); if (err) { @@ -2153,6 +2159,9 @@ check_user_ids (strlist_t *sp, err = keydb_search (hd, &desc, 1, NULL); if (gpg_err_code (err) == GPG_ERR_NOT_FOUND) { + if (DBG_LOOKUP) + log_debug ("%s: '%s' not found.\n", __func__, t->d); + if (error_if_not_found) { if (! rc) @@ -2195,6 +2204,9 @@ check_user_ids (strlist_t *sp, release_kbnode (kb); /* Continue the search. */ + if (DBG_LOOKUP) + log_debug ("%s: Check for duplicates for %s='%s'\n", + __func__, option, t->d); err = keydb_search (hd, &desc, 1, NULL); if (! err) /* Another result! */ diff --git a/g10/keydb.c b/g10/keydb.c index 22fec244c..40fb4c753 100644 --- a/g10/keydb.c +++ b/g10/keydb.c @@ -1692,7 +1692,16 @@ keydb_search (KEYDB_HANDLE hd, KEYDB_SEARCH_DESC *desc, while ((rc == -1 || gpg_err_code (rc) == GPG_ERR_EOF) && hd->current >= 0 && hd->current < hd->used) { - switch (hd->active[hd->current].type) + if (DBG_LOOKUP) + log_debug ("%s: searching %s (resource %d of %d)\n", + __func__, + hd->active[hd->current].type == KEYDB_RESOURCE_TYPE_KEYRING + ? "keyring" + : (hd->active[hd->current].type == KEYDB_RESOURCE_TYPE_KEYBOX + ? "keybox" : "unknown type"), + hd->current, hd->used); + + switch (hd->active[hd->current].type) { case KEYDB_RESOURCE_TYPE_NONE: BUG(); /* we should never see it here */ @@ -1707,6 +1716,17 @@ keydb_search (KEYDB_HANDLE hd, KEYDB_SEARCH_DESC *desc, descindex, &hd->skipped_long_blobs); break; } + + if (DBG_LOOKUP) + log_debug ("%s: searched %s (resource %d of %d) => %s\n", + __func__, + hd->active[hd->current].type == KEYDB_RESOURCE_TYPE_KEYRING + ? "keyring" + : (hd->active[hd->current].type == KEYDB_RESOURCE_TYPE_KEYBOX + ? "keybox" : "unknown type"), + hd->current, hd->used, + rc == -1 ? "EOF" : gpg_strerror (rc)); + if (rc == -1 || gpg_err_code (rc) == GPG_ERR_EOF) { /* EOF -> switch to next resource */ diff --git a/g10/keyring.c b/g10/keyring.c index 8ebc2e455..9a3638b3e 100644 --- a/g10/keyring.c +++ b/g10/keyring.c @@ -699,29 +699,51 @@ prepare_search (KEYRING_HANDLE hd) /* If the last key was a legacy key, we simply ignore the error so that we can easily use search_next. */ if (gpg_err_code (hd->current.error) == GPG_ERR_LEGACY_KEY) + { + if (DBG_LOOKUP) + log_debug ("%s: last error was GPG_ERR_LEGACY_KEY, clearing\n", + __func__); hd->current.error = 0; + } else + { + if (DBG_LOOKUP) + log_debug ("%s: returning last error: %s\n", + __func__, gpg_strerror (hd->current.error)); return hd->current.error; /* still in error state */ + } } if (hd->current.kr && !hd->current.eof) { if ( !hd->current.iobuf ) + { + if (DBG_LOOKUP) + log_debug ("%s: missing iobuf!\n", __func__); return GPG_ERR_GENERAL; /* Position invalid after a modify. */ + } return 0; /* okay */ } if (!hd->current.kr && hd->current.eof) + { + if (DBG_LOOKUP) + log_debug ("%s: EOF!\n", __func__); return -1; /* still EOF */ + } if (!hd->current.kr) { /* start search with first keyring */ hd->current.kr = hd->resource; if (!hd->current.kr) { + if (DBG_LOOKUP) + log_debug ("%s: keyring not available!\n", __func__); hd->current.eof = 1; return -1; /* keyring not available */ } assert (!hd->current.iobuf); } else { /* EOF */ + if (DBG_LOOKUP) + log_debug ("%s: EOF\n", __func__); iobuf_close (hd->current.iobuf); hd->current.iobuf = NULL; hd->current.kr = NULL; @@ -988,22 +1010,44 @@ keyring_search (KEYRING_HANDLE hd, KEYDB_SEARCH_DESC *desc, } } + if (DBG_LOOKUP) + log_debug ("%s: need_uid = %d; need_words = %d; need_keyid = %d; need_fpr = %d; any_skip = %d\n", + __func__, need_uid, need_words, need_keyid, need_fpr, any_skip); + rc = prepare_search (hd); if (rc) - return rc; + { + if (DBG_LOOKUP) + log_debug ("%s: prepare_search failed: %s (%d)\n", + __func__, gpg_strerror (rc), gpg_err_code (rc)); + return rc; + } use_offtbl = !!kr_offtbl; if (!use_offtbl) - ; + { + if (DBG_LOOKUP) + log_debug ("%s: no offset table.\n", __func__); + } else if (!kr_offtbl_ready) - need_keyid = 1; + { + if (DBG_LOOKUP) + log_debug ("%s: initializing offset table. (need_keyid: %d => 1)\n", + __func__, need_keyid); + need_keyid = 1; + } else if (ndesc == 1 && desc[0].mode == KEYDB_SEARCH_MODE_LONG_KID) { struct off_item *oi; + if (DBG_LOOKUP) + log_debug ("%s: look up by long key id, checking cache\n", __func__); + oi = lookup_offset_hash_table (kr_offtbl, desc[0].u.kid); if (!oi) { /* We know that we don't have this key */ + if (DBG_LOOKUP) + log_debug ("%s: cache says not present\n", __func__); hd->found.kr = NULL; hd->current.eof = 1; return -1; @@ -1047,6 +1091,9 @@ keyring_search (KEYRING_HANDLE hd, KEYDB_SEARCH_DESC *desc, pk_no = uid_no = 0; initial_skip = 1; /* skip until we see the start of a keyblock */ scanned_from_start = iobuf_tell (hd->current.iobuf) == 0; + if (DBG_LOOKUP) + log_debug ("%s: %ssearching from start of resource.\n", + __func__, scanned_from_start ? "" : "not "); while (!(rc=search_packet (hd->current.iobuf, &pkt, &offset, need_uid))) { byte afp[MAX_FINGERPRINT_LEN]; @@ -1143,6 +1190,10 @@ keyring_search (KEYRING_HANDLE hd, KEYDB_SEARCH_DESC *desc, free_packet (&pkt); continue; found: + if (DBG_LOOKUP) + log_debug ("%s: packet starting at offset %zx matched descriptor %zd\n", + __func__, offset, n); + /* Record which desc we matched on. Note this value is only meaningful if this function returns with no errors. */ if(descindex) @@ -1151,7 +1202,12 @@ keyring_search (KEYRING_HANDLE hd, KEYDB_SEARCH_DESC *desc, { if (desc[n].skipfnc && desc[n].skipfnc (desc[n].skipfncvalue, aki, uid_no)) - break; + { + if (DBG_LOOKUP) + log_debug ("%s: skipping match: desc %zd's skip function returned TRUE\n", + __func__, n); + break; + } } if (n == ndesc) goto real_found; @@ -1160,6 +1216,8 @@ keyring_search (KEYRING_HANDLE hd, KEYDB_SEARCH_DESC *desc, real_found: if (!rc) { + if (DBG_LOOKUP) + log_debug ("%s: returing success\n", __func__); hd->found.offset = main_offset; hd->found.kr = hd->current.kr; hd->found.pk_no = pk? pk_no : 0; @@ -1167,6 +1225,9 @@ keyring_search (KEYRING_HANDLE hd, KEYDB_SEARCH_DESC *desc, } else if (rc == -1) { + if (DBG_LOOKUP) + log_debug ("%s: no matches (EOF)\n", __func__); + hd->current.eof = 1; /* if we scanned all keyrings, we are sure that * all known key IDs are in our offtbl, mark that. */ @@ -1195,7 +1256,12 @@ keyring_search (KEYRING_HANDLE hd, KEYDB_SEARCH_DESC *desc, } } else - hd->current.error = rc; + { + if (DBG_LOOKUP) + log_debug ("%s: error encountered during search: %s (%d)\n", + __func__, gpg_strerror (rc), rc); + hd->current.error = rc; + } free_packet(&pkt); set_packet_list_mode(save_mode);