From c54e43d752c7187595c8c62a231e0b0d53c7fded Mon Sep 17 00:00:00 2001 From: David Howells Date: Thu, 10 May 2018 23:26:00 +0100 Subject: rxrpc: Fix missing start of call timeout The expect_rx_by call timeout is supposed to be set when a call is started to indicate that we need to receive a packet by that point. This is currently put back every time we receive a packet, but it isn't started when we first send a packet. Without this, the call may wait forever if the server doesn't deign to reply. Fix this by setting the timeout upon a successful UDP sendmsg call for the first DATA packet. The timeout is initiated only for initial transmission and not for subsequent retries as we don't want the retry mechanism to extend the timeout indefinitely. Fixes: a158bdd3247b ("rxrpc: Fix call timeouts") Reported-by: Marc Dionne Signed-off-by: David Howells --- net/rxrpc/output.c | 11 +++++++++++ 1 file changed, 11 insertions(+) (limited to 'net/rxrpc/output.c') diff --git a/net/rxrpc/output.c b/net/rxrpc/output.c index 7f1fc04775b3..6b9d27f0d7ec 100644 --- a/net/rxrpc/output.c +++ b/net/rxrpc/output.c @@ -414,6 +414,17 @@ done: rxrpc_timer_set_for_lost_ack); } } + + if (sp->hdr.seq == 1 && + !test_and_set_bit(RXRPC_CALL_BEGAN_RX_TIMER, + &call->flags)) { + unsigned long nowj = jiffies, expect_rx_by; + + expect_rx_by = nowj + call->next_rx_timo; + WRITE_ONCE(call->expect_rx_by, expect_rx_by); + rxrpc_reduce_call_timer(call, expect_rx_by, nowj, + rxrpc_timer_set_for_normal); + } } rxrpc_set_keepalive(call); -- cgit v1.2.3 From 6b47fe1d1ca3aec3a1a8623439c22fbf51016cd8 Mon Sep 17 00:00:00 2001 From: David Howells Date: Thu, 10 May 2018 23:26:01 +0100 Subject: rxrpc: Trace UDP transmission failure Add a tracepoint to log transmission failure from the UDP transport socket being used by AF_RXRPC. Signed-off-by: David Howells --- include/trace/events/rxrpc.h | 55 ++++++++++++++++++++++++++++++++++++++++++++ net/rxrpc/conn_event.c | 11 ++++++--- net/rxrpc/local_event.c | 3 ++- net/rxrpc/output.c | 23 ++++++++++++++++-- net/rxrpc/rxkad.c | 6 +++-- 5 files changed, 90 insertions(+), 8 deletions(-) (limited to 'net/rxrpc/output.c') diff --git a/include/trace/events/rxrpc.h b/include/trace/events/rxrpc.h index 497d0b67f421..077e664ac9a2 100644 --- a/include/trace/events/rxrpc.h +++ b/include/trace/events/rxrpc.h @@ -211,6 +211,20 @@ enum rxrpc_congest_change { rxrpc_cong_saw_nack, }; +enum rxrpc_tx_fail_trace { + rxrpc_tx_fail_call_abort, + rxrpc_tx_fail_call_ack, + rxrpc_tx_fail_call_data_frag, + rxrpc_tx_fail_call_data_nofrag, + rxrpc_tx_fail_call_final_resend, + rxrpc_tx_fail_conn_abort, + rxrpc_tx_fail_conn_challenge, + rxrpc_tx_fail_conn_response, + rxrpc_tx_fail_reject, + rxrpc_tx_fail_version_keepalive, + rxrpc_tx_fail_version_reply, +}; + #endif /* end __RXRPC_DECLARE_TRACE_ENUMS_ONCE_ONLY */ /* @@ -438,6 +452,19 @@ enum rxrpc_congest_change { EM(RXRPC_CALL_LOCAL_ERROR, "LocalError") \ E_(RXRPC_CALL_NETWORK_ERROR, "NetError") +#define rxrpc_tx_fail_traces \ + EM(rxrpc_tx_fail_call_abort, "CallAbort") \ + EM(rxrpc_tx_fail_call_ack, "CallAck") \ + EM(rxrpc_tx_fail_call_data_frag, "CallDataFrag") \ + EM(rxrpc_tx_fail_call_data_nofrag, "CallDataNofrag") \ + EM(rxrpc_tx_fail_call_final_resend, "CallFinalResend") \ + EM(rxrpc_tx_fail_conn_abort, "ConnAbort") \ + EM(rxrpc_tx_fail_conn_challenge, "ConnChall") \ + EM(rxrpc_tx_fail_conn_response, "ConnResp") \ + EM(rxrpc_tx_fail_reject, "Reject") \ + EM(rxrpc_tx_fail_version_keepalive, "VerKeepalive") \ + E_(rxrpc_tx_fail_version_reply, "VerReply") + /* * Export enum symbols via userspace. */ @@ -461,6 +488,7 @@ rxrpc_propose_ack_traces; rxrpc_propose_ack_outcomes; rxrpc_congest_modes; rxrpc_congest_changes; +rxrpc_tx_fail_traces; /* * Now redefine the EM() and E_() macros to map the enums to the strings that @@ -1404,6 +1432,33 @@ TRACE_EVENT(rxrpc_rx_icmp, &__entry->srx.transport) ); +TRACE_EVENT(rxrpc_tx_fail, + TP_PROTO(unsigned int debug_id, rxrpc_serial_t serial, int ret, + enum rxrpc_tx_fail_trace what), + + TP_ARGS(debug_id, serial, ret, what), + + TP_STRUCT__entry( + __field(unsigned int, debug_id ) + __field(rxrpc_serial_t, serial ) + __field(int, ret ) + __field(enum rxrpc_tx_fail_trace, what ) + ), + + TP_fast_assign( + __entry->debug_id = debug_id; + __entry->serial = serial; + __entry->ret = ret; + __entry->what = what; + ), + + TP_printk("c=%08x r=%x ret=%d %s", + __entry->debug_id, + __entry->serial, + __entry->ret, + __print_symbolic(__entry->what, rxrpc_tx_fail_traces)) + ); + #endif /* _TRACE_RXRPC_H */ /* This part must be outside protection */ diff --git a/net/rxrpc/conn_event.c b/net/rxrpc/conn_event.c index c717152070df..1350f1be8037 100644 --- a/net/rxrpc/conn_event.c +++ b/net/rxrpc/conn_event.c @@ -40,7 +40,7 @@ static void rxrpc_conn_retransmit_call(struct rxrpc_connection *conn, } __attribute__((packed)) pkt; struct rxrpc_ackinfo ack_info; size_t len; - int ioc; + int ret, ioc; u32 serial, mtu, call_id, padding; _enter("%d", conn->debug_id); @@ -135,10 +135,13 @@ static void rxrpc_conn_retransmit_call(struct rxrpc_connection *conn, break; } - kernel_sendmsg(conn->params.local->socket, &msg, iov, ioc, len); + ret = kernel_sendmsg(conn->params.local->socket, &msg, iov, ioc, len); conn->params.peer->last_tx_at = ktime_get_real(); + if (ret < 0) + trace_rxrpc_tx_fail(conn->debug_id, serial, ret, + rxrpc_tx_fail_call_final_resend); + _leave(""); - return; } /* @@ -236,6 +239,8 @@ static int rxrpc_abort_connection(struct rxrpc_connection *conn, ret = kernel_sendmsg(conn->params.local->socket, &msg, iov, 2, len); if (ret < 0) { + trace_rxrpc_tx_fail(conn->debug_id, serial, ret, + rxrpc_tx_fail_conn_abort); _debug("sendmsg failed: %d", ret); return -EAGAIN; } diff --git a/net/rxrpc/local_event.c b/net/rxrpc/local_event.c index 93b5d910b4a1..8325f1b86840 100644 --- a/net/rxrpc/local_event.c +++ b/net/rxrpc/local_event.c @@ -71,7 +71,8 @@ static void rxrpc_send_version_request(struct rxrpc_local *local, ret = kernel_sendmsg(local->socket, &msg, iov, 2, len); if (ret < 0) - _debug("sendmsg failed: %d", ret); + trace_rxrpc_tx_fail(local->debug_id, 0, ret, + rxrpc_tx_fail_version_reply); _leave(""); } diff --git a/net/rxrpc/output.c b/net/rxrpc/output.c index 6b9d27f0d7ec..f03de1c59ba3 100644 --- a/net/rxrpc/output.c +++ b/net/rxrpc/output.c @@ -210,6 +210,9 @@ int rxrpc_send_ack_packet(struct rxrpc_call *call, bool ping, if (ping) call->ping_time = now; conn->params.peer->last_tx_at = ktime_get_real(); + if (ret < 0) + trace_rxrpc_tx_fail(call->debug_id, serial, ret, + rxrpc_tx_fail_call_ack); if (call->state < RXRPC_CALL_COMPLETE) { if (ret < 0) { @@ -294,6 +297,10 @@ int rxrpc_send_abort_packet(struct rxrpc_call *call) ret = kernel_sendmsg(conn->params.local->socket, &msg, iov, 1, sizeof(pkt)); conn->params.peer->last_tx_at = ktime_get_real(); + if (ret < 0) + trace_rxrpc_tx_fail(call->debug_id, serial, ret, + rxrpc_tx_fail_call_abort); + rxrpc_put_connection(conn); return ret; @@ -387,6 +394,9 @@ int rxrpc_send_data_packet(struct rxrpc_call *call, struct sk_buff *skb, conn->params.peer->last_tx_at = ktime_get_real(); up_read(&conn->params.local->defrag_sem); + if (ret < 0) + trace_rxrpc_tx_fail(call->debug_id, serial, ret, + rxrpc_tx_fail_call_data_nofrag); if (ret == -EMSGSIZE) goto send_fragmentable; @@ -476,6 +486,10 @@ send_fragmentable: #endif } + if (ret < 0) + trace_rxrpc_tx_fail(call->debug_id, serial, ret, + rxrpc_tx_fail_call_data_frag); + up_write(&conn->params.local->defrag_sem); goto done; } @@ -493,6 +507,7 @@ void rxrpc_reject_packets(struct rxrpc_local *local) struct kvec iov[2]; size_t size; __be32 code; + int ret; _enter("%d", local->debug_id); @@ -527,7 +542,10 @@ void rxrpc_reject_packets(struct rxrpc_local *local) whdr.flags ^= RXRPC_CLIENT_INITIATED; whdr.flags &= RXRPC_CLIENT_INITIATED; - kernel_sendmsg(local->socket, &msg, iov, 2, size); + ret = kernel_sendmsg(local->socket, &msg, iov, 2, size); + if (ret < 0) + trace_rxrpc_tx_fail(local->debug_id, 0, ret, + rxrpc_tx_fail_reject); } rxrpc_free_skb(skb, rxrpc_skb_rx_freed); @@ -578,7 +596,8 @@ void rxrpc_send_keepalive(struct rxrpc_peer *peer) ret = kernel_sendmsg(peer->local->socket, &msg, iov, 2, len); if (ret < 0) - _debug("sendmsg failed: %d", ret); + trace_rxrpc_tx_fail(peer->debug_id, 0, ret, + rxrpc_tx_fail_version_keepalive); peer->last_tx_at = ktime_get_real(); _leave(""); diff --git a/net/rxrpc/rxkad.c b/net/rxrpc/rxkad.c index 588fea0dd362..6c0ae27fff84 100644 --- a/net/rxrpc/rxkad.c +++ b/net/rxrpc/rxkad.c @@ -664,7 +664,8 @@ static int rxkad_issue_challenge(struct rxrpc_connection *conn) ret = kernel_sendmsg(conn->params.local->socket, &msg, iov, 2, len); if (ret < 0) { - _debug("sendmsg failed: %d", ret); + trace_rxrpc_tx_fail(conn->debug_id, serial, ret, + rxrpc_tx_fail_conn_challenge); return -EAGAIN; } @@ -719,7 +720,8 @@ static int rxkad_send_response(struct rxrpc_connection *conn, ret = kernel_sendmsg(conn->params.local->socket, &msg, iov, 3, len); if (ret < 0) { - _debug("sendmsg failed: %d", ret); + trace_rxrpc_tx_fail(conn->debug_id, serial, ret, + rxrpc_tx_fail_conn_response); return -EAGAIN; } -- cgit v1.2.3