From: Jeffrey Altman Date: Sat, 18 Feb 2006 04:11:30 +0000 (+0000) Subject: rx-dpf-20060216 X-Git-Tag: openafs-devel-1_5_0~3 X-Git-Url: https://git.michaelhowe.org/gitweb/?a=commitdiff_plain;h=c135a53f926039009897b781555519ce366592da;p=packages%2Fo%2Fopenafs.git 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 df8535fa5..0f4defca3 100644 --- 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 b49614275..94997907f 100644 --- 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 15c238011..ec2436b89 100644 --- 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);