Add debug logs for better tracing

Signed-off-by: Jakub Jelen <jjelen@redhat.com>

6 files changed, 28 insertions, 0 deletions

diff --git a/src/cac.c b/src/cac.c
index c95488f..bd88f85 100644
--- a/src/cac.c
+++ b/src/cac.c
@@ -2143,6 +2143,8 @@ cac_new_pki_applet(int i, const unsigned char *cert,
     unsigned char pki_aid[] = { 0xa0, 0x00, 0x00, 0x00, 0x79, 0x01, 0x00 };
     int pki_aid_len = sizeof(pki_aid);
 
+    g_debug("%s: called", __func__);
+
     pki_aid[pki_aid_len-1] = i;
 
     applet_private = cac_new_pki_applet_private(i, cert, cert_len, key);
@@ -2252,6 +2254,8 @@ cac_card_init(VReader *reader, VCard *card,
         {0x90, 0x00},
     };
 
+    g_debug("%s: called", __func__);
+
     /* CAC Cards are VM Cards */
     vcard_set_type(card, VCARD_VM);
 
diff --git a/src/capcsc.c b/src/capcsc.c
index 937be06..236cba2 100644
--- a/src/capcsc.c
+++ b/src/capcsc.c
@@ -487,6 +487,8 @@ static PCSCContext context;
 
 int capcsc_init(void)
 {
+    g_debug("%s: called", __func__);
+
     g_mutex_init(&context.lock);
 
     if (init_pcsc(&context)) {
diff --git a/src/vcard.c b/src/vcard.c
index 9c1bcf2..e94ee5d 100644
--- a/src/vcard.c
+++ b/src/vcard.c
@@ -141,6 +141,8 @@ vcard_new(VCardEmul *private, VCardEmulFree private_free)
 {
     VCard *new_card;
 
+    g_debug("%s: called", __func__);
+
     new_card = g_new0(VCard, 1);
     new_card->type = VCARD_VM;
     new_card->vcard_private = private;
@@ -204,6 +206,8 @@ vcard_set_atr_func(VCard *card, VCardGetAtr get_atr)
 VCardStatus
 vcard_add_applet(VCard *card, VCardApplet *applet)
 {
+    g_debug("%s: called", __func__);
+
     applet->next = card->applet_list;
     card->applet_list = applet;
     /* if our card-type is direct, always call the applet */
diff --git a/src/vcard_emul_nss.c b/src/vcard_emul_nss.c
index ad5f62a..564ba4e 100644
--- a/src/vcard_emul_nss.c
+++ b/src/vcard_emul_nss.c
@@ -608,6 +608,8 @@ vcard_emul_make_card(VReader *reader,
     VCardEmulType type;
     const char *params;
 
+    g_debug("%s: called", __func__);
+
     type = vcard_emul_get_type(reader);
 
     /* ignore the inserted card */
@@ -654,6 +656,8 @@ vcard_emul_mirror_card(VReader *vreader)
     PK11SlotInfo *slot;
     VCard *card;
 
+    g_debug("%s: called", __func__);
+
     slot = vcard_emul_reader_get_slot(vreader);
     if (slot == NULL) {
         return NULL;
@@ -682,6 +686,7 @@ vcard_emul_mirror_card(VReader *vreader)
         CERTCertificate *cert;
         SECStatus rv;
 
+        g_debug("%s: Found certificate", __func__);
         rv = PK11_ReadRawAttribute(PK11_TypeGeneric, thisObj,
                                    CKA_VALUE, &derCert);
         if (rv != SECSuccess) {
@@ -905,6 +910,8 @@ vcard_emul_init(const VCardEmulOptions *options)
     SECMODModuleList *mlp;
     int i;
 
+    g_debug("%s: called", __func__);
+
     if (vcard_emul_init_called) {
         return VCARD_EMUL_INIT_ALREADY_INITED;
     }
@@ -929,6 +936,7 @@ vcard_emul_init(const VCardEmulOptions *options)
             return VCARD_EMUL_FAIL;
         }
 
+        g_debug("%s: returning with passthrough initialized", __func__);
         return VCARD_EMUL_OK;
     }
 #endif
@@ -1018,6 +1026,7 @@ vcard_emul_init(const VCardEmulOptions *options)
     /* if we aren't suppose to use hw, skip looking up hardware tokens */
     if (!options->use_hw) {
         nss_emul_init = has_readers;
+        g_debug("%s: returning: Not using HW", __func__);
         return has_readers ? VCARD_EMUL_OK : VCARD_EMUL_FAIL;
     }
 
@@ -1040,6 +1049,7 @@ vcard_emul_init(const VCardEmulOptions *options)
             continue;
         }
 
+        g_debug("%s: Listing modules, trying %s", __func__, module->commonName);
         for (i = 0; i < module->slotCount; i++) {
             PK11SlotInfo *slot = module->slots[i];
 
@@ -1063,12 +1073,16 @@ vcard_emul_init(const VCardEmulOptions *options)
             vreader = vreader_new(PK11_GetSlotName(slot), vreader_emul,
                                   vreader_emul_delete);
             vreader_add_reader(vreader);
+            g_debug("%s: Added reader from slot %s", __func__,
+                    PK11_GetSlotName(slot));
 
             if (PK11_IsPresent(slot)) {
                 VCard *vcard;
                 vcard = vcard_emul_mirror_card(vreader);
                 vreader_insert_card(vreader, vcard);
                 vcard_emul_init_series(vreader, vcard);
+                g_debug("%s: Added card to the reader %s", __func__,
+                        vreader_get_name(vreader));
                 vcard_free(vcard);
             }
         }
diff --git a/src/vcard_emul_type.c b/src/vcard_emul_type.c
index a24e503..65fcd8b 100644
--- a/src/vcard_emul_type.c
+++ b/src/vcard_emul_type.c
@@ -23,6 +23,8 @@ VCardStatus vcard_init(VReader *vreader, VCard *vcard,
 {
     int rv;
 
+    g_debug("%s: called", __func__);
+
     switch (type) {
     case VCARD_EMUL_NONE:
         break;
diff --git a/src/vreader.c b/src/vreader.c
index ce0009b..1005508 100644
--- a/src/vreader.c
+++ b/src/vreader.c
@@ -259,6 +259,8 @@ vreader_xfr_bytes(VReader *reader,
     VCard *card = vreader_get_card(reader);
     int size;
 
+    g_debug("%s: called", __func__);
+
     if (card == NULL) {
         return VREADER_NO_CARD;
     }