LU-17935 kfilnd: Cleanup debug logging

Log messages that refer to a struct kfilnd_transaction should print
the pointer to the struct with "TN %p".

Assign kfilnd_transaction::msg_type in the kfilnd_process_rx_event
path so that debug messages show the correct message type.

HPE-bug-id: LUs-11325
Test-Parameters: trivial
Signed-off-by: Chris Horn <chris.horn@hpe.com>
Change-Id: Iabe3bf245b64f1eb66c85259072491c723fb6119
Reviewed-on: https://review.whamcloud.com/c/fs/lustre-release/+/55398
Reviewed-by: Caleb Carlson <caleb.carlson@hpe.com>
Reviewed-by: Ron Gredvig <ron.gredvig@hpe.com>
Reviewed-by: Oleg Drokin <green@whamcloud.com>
Tested-by: jenkins <devops@whamcloud.com>
Tested-by: Maloo <maloo@whamcloud.com>

diff --git a/lnet/klnds/kfilnd/kfilnd.h b/lnet/klnds/kfilnd/kfilnd.h
index 82b50e5..3ee5b88 100644 (file)
--- a/lnet/klnds/kfilnd/kfilnd.h
+++ b/lnet/klnds/kfilnd/kfilnd.h
@@ -622,7 +622,7 @@ struct kfilnd_msg {
        } while (0)
 
 #define KFILND_TN_DIR_ERROR(tn, fmt, dir, ...) \
-       CNETERR("Transaction ID %p: %s:%u %s %s(%p):0x%llx " fmt "\n", \
+       CNETERR("TN %p: %s:%u %s %s(%p):0x%llx " fmt "\n", \
                (tn), \
                libcfs_nidstr(&(tn)->tn_ep->end_dev->kfd_ni->ni_nid), \
                (tn)->tn_ep->end_context_id, dir, \

diff --git a/lnet/klnds/kfilnd/kfilnd_ep.c b/lnet/klnds/kfilnd/kfilnd_ep.c
index 580ffad..93290d3 100644 (file)
--- a/lnet/klnds/kfilnd/kfilnd_ep.c
+++ b/lnet/klnds/kfilnd/kfilnd_ep.c
@@ -264,14 +264,14 @@ int kfilnd_ep_post_tagged_send(struct kfilnd_ep *ep,
        case 0:
        case -EAGAIN:
                KFILND_EP_DEBUG(ep,
-                               "Transaction ID %p: %s tagged send of with tag 0x%x to peer 0x%llx: rc=%d",
+                               "TN %p: %s tagged send of with tag 0x%x to peer 0x%llx: rc=%d",
                                tn, rc ? "Failed to post" : "Posted",
                                tn->tn_response_mr_key, tn->tn_target_addr, rc);
                break;
 
        default:
                KFILND_EP_ERROR(ep,
-                               "Transaction ID %p: Failed to post tagged send with tag 0x%x to peer 0x%llx: rc=%d",
+                               "TN %p: Failed to post tagged send with tag 0x%x to peer 0x%llx: rc=%d",
                                tn, tn->tn_response_mr_key,
                                tn->tn_target_addr, rc);
        }
@@ -369,14 +369,14 @@ int kfilnd_ep_post_tagged_recv(struct kfilnd_ep *ep,
        case 0:
        case -EAGAIN:
                KFILND_EP_DEBUG(ep,
-                               "Transaction ID %p: %s tagged recv of %u bytes (%u frags) with tag 0x%llx: rc=%d",
+                               "TN %p: %s tagged recv of %u bytes (%u frags) with tag 0x%llx: rc=%d",
                                tn, rc ? "Failed to post" : "Posted",
                                tn->tn_nob, tn->tn_num_iovec, msg.tag, rc);
                break;
 
        default:
                KFILND_EP_ERROR(ep,
-                               "Transaction ID %p: Failed to post tagged recv of %u bytes (%u frags) with tag 0x%llx: rc=%d",
+                               "TN %p: Failed to post tagged recv of %u bytes (%u frags) with tag 0x%llx: rc=%d",
                                tn, tn->tn_nob, tn->tn_num_iovec, msg.tag, rc);
        }
 
@@ -434,14 +434,14 @@ int kfilnd_ep_post_send(struct kfilnd_ep *ep, struct kfilnd_transaction *tn)
        case 0:
        case -EAGAIN:
                KFILND_EP_DEBUG(ep,
-                               "Transaction ID %p: %s send of %lu bytes to peer 0x%llx: rc=%d",
+                               "TN %p: %s send of %lu bytes to peer 0x%llx: rc=%d",
                                tn, rc ? "Failed to post" : "Posted",
                                len, tn->tn_target_addr, rc);
                break;
 
        default:
                KFILND_EP_ERROR(ep,
-                               "Transaction ID %p: Failed to post send of %lu bytes to peer 0x%llx: rc=%d",
+                               "TN %p: Failed to post send of %lu bytes to peer 0x%llx: rc=%d",
                                tn, len, tn->tn_target_addr, rc);
        }
 

diff --git a/lnet/klnds/kfilnd/kfilnd_tn.c b/lnet/klnds/kfilnd/kfilnd_tn.c
index a812097..e6b3ae8 100644 (file)
--- a/lnet/klnds/kfilnd/kfilnd_tn.c
+++ b/lnet/klnds/kfilnd/kfilnd_tn.c
@@ -354,23 +354,26 @@ void kfilnd_tn_process_rx_event(struct kfilnd_immediate_buffer *bufdesc,
                                struct kfilnd_msg *rx_msg, int msg_size)
 {
        struct kfilnd_transaction *tn;
+       struct kfilnd_ep *ep = bufdesc->immed_end;
        bool alloc_msg = true;
        int rc;
        enum tn_events event = TN_EVENT_RX_HELLO;
+       enum kfilnd_msg_type msg_type;
 
        /* Increment buf ref count for this work */
        atomic_inc(&bufdesc->immed_ref);
 
        /* Unpack the message */
-       rc = kfilnd_tn_unpack_msg(bufdesc->immed_end, rx_msg, msg_size);
+       rc = kfilnd_tn_unpack_msg(ep, rx_msg, msg_size);
        if (rc || CFS_FAIL_CHECK(CFS_KFI_FAIL_MSG_UNPACK)) {
                kfilnd_ep_imm_buffer_put(bufdesc);
-               KFILND_EP_ERROR(bufdesc->immed_end,
-                               "Failed to unpack message %d", rc);
+               KFILND_EP_ERROR(ep, "Failed to unpack message %d", rc);
                return;
        }
 
-       switch ((enum kfilnd_msg_type)rx_msg->type) {
+       msg_type = (enum kfilnd_msg_type)rx_msg->type;
+
+       switch (msg_type) {
        case KFILND_MSG_IMMEDIATE:
        case KFILND_MSG_BULK_PUT_REQ:
        case KFILND_MSG_BULK_GET_REQ:
@@ -384,14 +387,13 @@ void kfilnd_tn_process_rx_event(struct kfilnd_immediate_buffer *bufdesc,
                 * Allocate a Tn structure, set its values, then launch the
                 * receive.
                 */
-               tn = kfilnd_tn_alloc(bufdesc->immed_end->end_dev,
-                                    bufdesc->immed_end->end_cpt,
+               tn = kfilnd_tn_alloc(ep->end_dev, ep->end_cpt,
                                     rx_msg->srcnid, alloc_msg, false,
                                     false);
                if (IS_ERR(tn)) {
                        kfilnd_ep_imm_buffer_put(bufdesc);
-                       KFILND_EP_ERROR(bufdesc->immed_end,
-                                       "Failed to allocate transaction struct: rc=%ld",
+                       KFILND_EP_ERROR(ep,
+                               "Failed to allocate transaction struct: rc=%ld",
                                        PTR_ERR(tn));
                        return;
                }
@@ -399,16 +401,16 @@ void kfilnd_tn_process_rx_event(struct kfilnd_immediate_buffer *bufdesc,
                tn->tn_rx_msg.msg = rx_msg;
                tn->tn_rx_msg.length = msg_size;
                tn->tn_posted_buf = bufdesc;
+               tn->msg_type = msg_type;
 
-               KFILND_EP_DEBUG(bufdesc->immed_end, "%s transaction ID %u",
-                               msg_type_to_str((enum kfilnd_msg_type)rx_msg->type),
+               KFILND_EP_DEBUG(ep, "%s TN %p tmk %u",
+                               msg_type_to_str(tn->msg_type), tn,
                                tn->tn_mr_key);
                break;
 
        default:
-               KFILND_EP_ERROR(bufdesc->immed_end,
-                               "Unhandled kfilnd message type: %d",
-                               (enum kfilnd_msg_type)rx_msg->type);
+               KFILND_EP_ERROR(ep, "Unhandled kfilnd message type: %d",
+                               msg_type);
                LBUG();
        };
 
@@ -1621,7 +1623,7 @@ static struct kfilnd_transaction *kfilnd_tn_alloc_common(struct kfilnd_ep *ep,
        tn->tn_alloc_ts = tn_alloc_ts;
        tn->tn_state_ts = ktime_get();
 
-       KFILND_EP_DEBUG(ep, "Transaction ID %u allocated", tn->tn_mr_key);
+       KFILND_EP_DEBUG(ep, "TN %p allocated with tmk %u", tn, tn->tn_mr_key);
 
        return tn;