rx-dpf-20060216

when dpf is in use, log error codes from abort packets and perform
ntoh translation of addresses and port numbers.

diff --git a/src/rx/rx.c b/src/rx/rx.c
index df8535fa5224ca954270cde0b45103b1c4516a65..0f4defca3a12bec7ba9df7de4d25b88802d7c41c 100644 (file)
--- a/src/rx/rx.c
+++ b/src/rx/rx.c
@@ -754,7 +754,7 @@ rx_NewConnection(register afs_uint32 shost, u_short sport, u_short sservice,
     SPLVAR;
 
     clock_NewTime();
-    dpf(("rx_NewConnection(host %x, port %u, service %u, securityObject %x, serviceSecurityIndex %d)\n", shost, sport, sservice, securityObject, serviceSecurityIndex));
+    dpf(("rx_NewConnection(host %x, port %u, service %u, securityObject %x, serviceSecurityIndex %d)\n", ntohl(shost), ntohs(sport), sservice, securityObject, serviceSecurityIndex));
 
     /* Vasilsi said: "NETPRI protects Cid and Alloc", but can this be true in
      * the case of kmem_alloc? */
@@ -1839,7 +1839,7 @@ rx_EndCall(register struct rx_call *call, afs_int32 rc)
 
 
 
-    dpf(("rx_EndCall(call %x)\n", call));
+    dpf(("rx_EndCall(call %x rc %d error %d abortCode %d)\n", call, rc, call->error, call->abortCode));
 
     NETPRI;
     MUTEX_ENTER(&call->lock);
@@ -2435,7 +2435,7 @@ rxi_ReceivePacket(register struct rx_packet *np, osi_socket socket,
     packetType = (np->header.type > 0 && np->header.type < RX_N_PACKET_TYPES)
        ? rx_packetTypes[np->header.type - 1] : "*UNKNOWN*";
     dpf(("R %d %s: %x.%d.%d.%d.%d.%d.%d flags %d, packet %x",
-        np->header.serial, packetType, host, port, np->header.serviceId,
+        np->header.serial, packetType, ntohl(host), htohs(port), np->header.serviceId,
         np->header.epoch, np->header.cid, np->header.callNumber,
         np->header.seq, np->header.flags, np));
 #endif
@@ -2506,13 +2506,16 @@ rxi_ReceivePacket(register struct rx_packet *np, osi_socket socket,
     /* Check for connection-only requests (i.e. not call specific). */
     if (np->header.callNumber == 0) {
        switch (np->header.type) {
-       case RX_PACKET_TYPE_ABORT:
+       case RX_PACKET_TYPE_ABORT: {
            /* What if the supplied error is zero? */
-           rxi_ConnectionError(conn, ntohl(rx_GetInt32(np, 0)));
+           afs_int32 errcode = ntohl(rx_GetInt32(np, 0));
+           dpf(("rxi_ReceivePacket ABORT rx_GetInt32 = %d", errcode));
+           rxi_ConnectionError(conn, errcode);
            MUTEX_ENTER(&conn->conn_data_lock);
            conn->refCount--;
            MUTEX_EXIT(&conn->conn_data_lock);
            return np;
+       }
        case RX_PACKET_TYPE_CHALLENGE:
            tnp = rxi_ReceiveChallengePacket(conn, np, 1);
            MUTEX_ENTER(&conn->conn_data_lock);
@@ -2609,7 +2612,7 @@ rxi_ReceivePacket(register struct rx_packet *np, osi_socket socket,
            MUTEX_EXIT(&conn->conn_call_lock);
            *call->callNumber = np->header.callNumber;
            if (np->header.callNumber == 0) 
-               dpf(("RecPacket call 0 %d %s: %x.%u.%u.%u.%u.%u.%u flags %d, packet %lx resend %d.%0.3d len %d", np->header.serial, rx_packetTypes[np->header.type - 1], conn->peer->host, conn->peer->port, np->header.serial, np->header.epoch, np->header.cid, np->header.callNumber, np->header.seq, np->header.flags, (unsigned long)np, np->retryTime.sec, np->retryTime.usec / 1000, np->length));
+               dpf(("RecPacket call 0 %d %s: %x.%u.%u.%u.%u.%u.%u flags %d, packet %lx resend %d.%0.3d len %d", np->header.serial, rx_packetTypes[np->header.type - 1], ntohl(conn->peer->host), ntohs(conn->peer->port), np->header.serial, np->header.epoch, np->header.cid, np->header.callNumber, np->header.seq, np->header.flags, (unsigned long)np, np->retryTime.sec, np->retryTime.usec / 1000, np->length));
 
            call->state = RX_STATE_PRECALL;
            clock_GetTime(&call->queueTime);
@@ -2674,7 +2677,7 @@ rxi_ReceivePacket(register struct rx_packet *np, osi_socket socket,
            rxi_ResetCall(call, 0);
            *call->callNumber = np->header.callNumber;
            if (np->header.callNumber == 0) 
-               dpf(("RecPacket call 0 %d %s: %x.%u.%u.%u.%u.%u.%u flags %d, packet %lx resend %d.%0.3d len %d", np->header.serial, rx_packetTypes[np->header.type - 1], conn->peer->host, conn->peer->port, np->header.serial, np->header.epoch, np->header.cid, np->header.callNumber, np->header.seq, np->header.flags, (unsigned long)np, np->retryTime.sec, np->retryTime.usec / 1000, np->length));
+               dpf(("RecPacket call 0 %d %s: %x.%u.%u.%u.%u.%u.%u flags %d, packet %lx resend %d.%0.3d len %d", np->header.serial, rx_packetTypes[np->header.type - 1], ntohl(conn->peer->host), ntohs(conn->peer->port), np->header.serial, np->header.epoch, np->header.cid, np->header.callNumber, np->header.seq, np->header.flags, (unsigned long)np, np->retryTime.sec, np->retryTime.usec / 1000, np->length));
 
            call->state = RX_STATE_PRECALL;
            clock_GetTime(&call->queueTime);
@@ -2850,16 +2853,19 @@ rxi_ReceivePacket(register struct rx_packet *np, osi_socket socket,
        }
        np = rxi_ReceiveAckPacket(call, np, 1);
        break;
-    case RX_PACKET_TYPE_ABORT:
+    case RX_PACKET_TYPE_ABORT: {
        /* An abort packet: reset the call, passing the error up to the user. */
        /* What if error is zero? */
        /* What if the error is -1? the application will treat it as a timeout. */
-       rxi_CallError(call, ntohl(*(afs_int32 *) rx_DataOf(np)));
+       afs_int32 errdata = ntohl(*(afs_int32 *) rx_DataOf(np));
+       dpf(("rxi_ReceivePacket ABORT rx_DataOf = %d", errdata));
+       rxi_CallError(call, errdata);
        MUTEX_EXIT(&call->lock);
        MUTEX_ENTER(&conn->conn_data_lock);
        conn->refCount--;
        MUTEX_EXIT(&conn->conn_data_lock);
        return np;              /* xmitting; drop packet */
+    }
     case RX_PACKET_TYPE_BUSY:
        /* XXXX */
        break;
@@ -3447,6 +3453,34 @@ rxi_UpdatePeerReach(struct rx_connection *conn, struct rx_call *acall)
        MUTEX_EXIT(&conn->conn_data_lock);
 }
 
+static const char *
+rx_ack_reason(int reason)
+{
+    switch (reason) {
+    case RX_ACK_REQUESTED:
+       return "requested";
+    case RX_ACK_DUPLICATE:
+       return "duplicate";
+    case RX_ACK_OUT_OF_SEQUENCE:
+       return "sequence";
+    case RX_ACK_EXCEEDS_WINDOW:
+       return "window";
+    case RX_ACK_NOSPACE:
+       return "nospace";
+    case RX_ACK_PING:
+       return "ping";
+    case RX_ACK_PING_RESPONSE:
+       return "response";
+    case RX_ACK_DELAY:
+       return "delay";
+    case RX_ACK_IDLE:
+       return "idle";
+    default:
+       return "unknown!!";
+    }
+}
+
+
 /* rxi_ComputePeerNetStats
  *
  * Called exclusively by rxi_ReceiveAckPacket to compute network link
@@ -3519,6 +3553,28 @@ rxi_ReceiveAckPacket(register struct rx_call *call, struct rx_packet *np,
        rxi_UpdatePeerReach(conn, call);
 
 #ifdef RXDEBUG
+#ifdef AFS_NT40_ENV
+    if (rxdebug_active) {
+       char msg[512];
+       size_t len;
+
+       len = _snprintf(msg, sizeof(msg),
+                       "tid[%d] RACK: reason %s serial %u previous %u seq %u skew %d first %u acks %u space %u ",
+                        GetCurrentThreadId(), rx_ack_reason(ap->reason), 
+                        ntohl(ap->serial), ntohl(ap->previousPacket),
+                        (unsigned int)np->header.seq, (unsigned int)skew, 
+                        ntohl(ap->firstPacket), ap->nAcks, ntohs(ap->bufferSpace) );
+       if (nAcks) {
+           int offset;
+
+           for (offset = 0; offset < nAcks && len < sizeof(msg); offset++) 
+               msg[len++] = (ap->acks[offset] == RX_ACK_TYPE_NACK ? '-' : '*');
+       }
+       msg[len++]='\n';
+       msg[len] = '\0';
+       OutputDebugString(msg);
+    }
+#else /* AFS_NT40_ENV */
     if (rx_Log) {
        fprintf(rx_Log,
                "RACK: reason %x previous %u seq %u serial %u skew %d first %u",
@@ -3533,6 +3589,7 @@ rxi_ReceiveAckPacket(register struct rx_call *call, struct rx_packet *np,
        }
        putc('\n', rx_Log);
     }
+#endif /* AFS_NT40_ENV */
 #endif
 
     /* Update the outgoing packet skew value to the latest value of
@@ -3636,7 +3693,7 @@ rxi_ReceiveAckPacket(register struct rx_call *call, struct rx_packet *np,
                } else {
                    call->nSoftAcked++;
                }
-           } else {
+           } else /* RX_ACK_TYPE_NACK */ {
                tp->flags &= ~RX_PKTFLAG_ACKED;
                missing = 1;
            }
@@ -4332,6 +4389,9 @@ rxi_ConnectionError(register struct rx_connection *conn,
 {
     if (error) {
        register int i;
+
+       dpf(("rxi_ConnectionError conn %x error %d", conn, error));
+
        MUTEX_ENTER(&conn->conn_data_lock);
        if (conn->challengeEvent)
            rxevent_Cancel(conn->challengeEvent, (struct rx_call *)0, 0);
@@ -4360,8 +4420,10 @@ rxi_ConnectionError(register struct rx_connection *conn,
 void
 rxi_CallError(register struct rx_call *call, afs_int32 error)
 {
+    dpf(("rxi_CallError call %x error %d call->error %d", call, error, call->error));
     if (call->error)
        error = call->error;
+
 #ifdef RX_GLOBAL_RXLOCK_KERNEL
     if (!((call->flags & RX_CALL_TQ_BUSY) || (call->tqWaiters > 0))) {
        rxi_ResetCall(call, 0);
@@ -4709,8 +4771,30 @@ rxi_SendAck(register struct rx_call *call,
        p->header.flags |= RX_CLIENT_INITIATED;
 
 #ifdef RXDEBUG
+#ifdef AFS_NT40_ENV
+    if (rxdebug_active) {
+       char msg[512];
+       size_t len;
+
+       len = _snprintf(msg, sizeof(msg),
+                       "tid[%d] SACK: reason %s serial %u previous %u seq %u first %u acks %u space %u ",
+                        GetCurrentThreadId(), rx_ack_reason(ap->reason), 
+                        ntohl(ap->serial), ntohl(ap->previousPacket),
+                        (unsigned int)p->header.seq, ntohl(ap->firstPacket),
+                        ap->nAcks, ntohs(ap->bufferSpace) );
+       if (ap->nAcks) {
+           int offset;
+
+           for (offset = 0; offset < ap->nAcks && len < sizeof(msg); offset++) 
+               msg[len++] = (ap->acks[offset] == RX_ACK_TYPE_NACK ? '-' : '*');
+       }
+       msg[len++]='\n';
+       msg[len] = '\0';
+       OutputDebugString(msg);
+    }
+#else /* AFS_NT40_ENV */
     if (rx_Log) {
-       fprintf(rx_Log, "SACK: reason %x previous %u seq %u first %u",
+       fprintf(rx_Log, "SACK: reason %x previous %u seq %u first %u ",
                ap->reason, ntohl(ap->previousPacket),
                (unsigned int)p->header.seq, ntohl(ap->firstPacket));
        if (ap->nAcks) {
@@ -4720,8 +4804,8 @@ rxi_SendAck(register struct rx_call *call,
        }
        putc('\n', rx_Log);
     }
+#endif /* AFS_NT40_ENV */
 #endif
-
     {
        register int i, nbytes = p->length;
 
@@ -6075,7 +6159,7 @@ rxi_DebugPrint(char *format, int a1, int a2, int a3, int a4, int a5, int a6,
 #ifdef AFS_NT40_ENV
     char msg[512];
     char tformat[256];
-    int len;
+    size_t len;
 
     len = _snprintf(tformat, sizeof(tformat), "tid[%d] %s", GetCurrentThreadId(), format);
 

diff --git a/src/rx/rx_globals.h b/src/rx/rx_globals.h
index b49614275e22bde7da8ab67158314a190a17ddb2..94997907f87963f5775e77cde2701d9eeedc3465 100644 (file)
--- a/src/rx/rx_globals.h
+++ b/src/rx/rx_globals.h
@@ -62,6 +62,7 @@ EXT struct clock rx_softAckDelay;
 /* Variable to allow introduction of network unreliability */
 #ifdef RXDEBUG
 EXT int rx_intentionallyDroppedPacketsPer100 INIT(0);  /* Dropped on Send */
+EXT int rx_intentionallyDroppedOnReadPer100  INIT(0);  /* Dropped on Read */
 #endif
 
 /* extra packets to add to the quota */

diff --git a/src/rx/rx_packet.c b/src/rx/rx_packet.c
index 15c2380117f9573cb9b7f72d5480eeba6944efaf..ec2436b892d56611239c62b0ee9b50f0b2d6d55c 100644 (file)
--- a/src/rx/rx_packet.c
+++ b/src/rx/rx_packet.c
@@ -1405,10 +1405,23 @@ rxi_ReadPacket(osi_socket socket, register struct rx_packet *p, afs_uint32 * hos
            rx_stats.bogusPacketOnRead++;
            rx_stats.bogusHost = from.sin_addr.s_addr;
            MUTEX_EXIT(&rx_stats_mutex);
-           dpf(("B: bogus packet from [%x,%d] nb=%d", from.sin_addr.s_addr,
-                from.sin_port, nbytes));
+           dpf(("B: bogus packet from [%x,%d] nb=%d", ntohl(from.sin_addr.s_addr),
+                ntohs(from.sin_port), nbytes));
        }
        return 0;
+    } else if ((rx_intentionallyDroppedOnReadPer100 > 0)
+               && (random() % 100 < rx_intentionallyDroppedOnReadPer100)) {
+       rxi_DecodePacketHeader(p);
+
+       *host = from.sin_addr.s_addr;
+       *port = from.sin_port;
+
+       dpf(("Dropped %d %s: %x.%u.%u.%u.%u.%u.%u flags %d len %d",
+             p->header.serial, rx_packetTypes[p->header.type - 1], ntohl(host), ntohs(port), p->header.serial, 
+             p->header.epoch, p->header.cid, p->header.callNumber, p->header.seq, p->header.flags, 
+             p->length));
+       rxi_TrimDataBufs(p, 1);
+       return 0;
     } else {
        /* Extract packet header. */
        rxi_DecodePacketHeader(p);
@@ -2226,7 +2239,7 @@ rxi_SendPacket(struct rx_call *call, struct rx_connection *conn,
 #endif
 #ifdef RXDEBUG
     }
-    dpf(("%c %d %s: %x.%u.%u.%u.%u.%u.%u flags %d, packet %lx resend %d.%0.3d len %d", deliveryType, p->header.serial, rx_packetTypes[p->header.type - 1], peer->host, peer->port, p->header.serial, p->header.epoch, p->header.cid, p->header.callNumber, p->header.seq, p->header.flags, (unsigned long)p, p->retryTime.sec, p->retryTime.usec / 1000, p->length));
+    dpf(("%c %d %s: %x.%u.%u.%u.%u.%u.%u flags %d, packet %lx resend %d.%0.3d len %d", deliveryType, p->header.serial, rx_packetTypes[p->header.type - 1], ntohl(peer->host), ntohs(peer->port), p->header.serial, p->header.epoch, p->header.cid, p->header.callNumber, p->header.seq, p->header.flags, (unsigned long)p, p->retryTime.sec, p->retryTime.usec / 1000, p->length));
 #endif
     MUTEX_ENTER(&rx_stats_mutex);
     rx_stats.packetsSent[p->header.type - 1]++;
@@ -2412,7 +2425,7 @@ rxi_SendPacketList(struct rx_call *call, struct rx_connection *conn,
 
     assert(p != NULL);
 
-    dpf(("%c %d %s: %x.%u.%u.%u.%u.%u.%u flags %d, packet %lx resend %d.%0.3d len %d", deliveryType, p->header.serial, rx_packetTypes[p->header.type - 1], peer->host, peer->port, p->header.serial, p->header.epoch, p->header.cid, p->header.callNumber, p->header.seq, p->header.flags, (unsigned long)p, p->retryTime.sec, p->retryTime.usec / 1000, p->length));
+    dpf(("%c %d %s: %x.%u.%u.%u.%u.%u.%u flags %d, packet %lx resend %d.%0.3d len %d", deliveryType, p->header.serial, rx_packetTypes[p->header.type - 1], ntohl(peer->host), ntohs(peer->port), p->header.serial, p->header.epoch, p->header.cid, p->header.callNumber, p->header.seq, p->header.flags, (unsigned long)p, p->retryTime.sec, p->retryTime.usec / 1000, p->length));
 
 #endif
     MUTEX_ENTER(&rx_stats_mutex);