Uploaded image for project: 'Qpid Dispatch'
  1. Qpid Dispatch
  2. DISPATCH-2091

TCP adaptor does not close listener connection when RX window is full

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Blocker
    • Resolution: Fixed
    • None
    • 1.16.0
    • Protocol Adaptors
    • None

    Description

      A two-router network has TCP Listener on A and TCP Connector on B.

      The test program is a iperf3 server and a client run with

          iperf3 -c 127.0.0.1 -p 5202 -t 2

      Iperf3 creates two connections. The low-volume connection closes OK. The high-volume connection receives a network FIN but never responds with FIN/ACK.

      TCP logging for the stuck connection shows that the RX windows is full. When proton signals that read data is available the adaptor ignores it. This probably interrupts the normal event sequence and a DISCONNECTED event never arrives.

      The event sequence is

      2021-04-28 17:13:48.502875 -0400 TCP_ADAPTOR (trace) [C3][L28] handle_incoming PNRC_READ for listener connection. read_closed:F, flow_enabled:T
2021-04-28 17:13:48.502896 -0400 TCP_ADAPTOR (debug) [C3] pn_raw_connection_take_read_buffers() took 16, freed 0
2021-04-28 17:13:48.502907 -0400 TCP_ADAPTOR (debug) [C3][L28] Granting 16 to pn_raw_connection_give_read_buffers()
2021-04-28 17:13:48.503126 -0400 TCP_ADAPTOR (trace) [C3][L28][D22] Continuing listener message with 8192 bytes
2021-04-28 17:13:48.503140 -0400 TCP_ADAPTOR (debug) [C3] PN_RAW_CONNECTION_READ Read 8192 bytes. Total read 45482021 bytes
2021-04-28 17:13:48.503188 -0400 TCP_ADAPTOR (debug) [C3] PN_RAW_CONNECTION_READ listener Event 
2021-04-28 17:13:48.503210 -0400 TCP_ADAPTOR (trace) [C3][L28] handle_incoming PNRC_READ for listener connection. read_closed:F, flow_enabled:T
2021-04-28 17:13:48.503229 -0400 TCP_ADAPTOR (trace) [C3] TCP RX window CLOSED: bytes in=45488165 unacked=1460232
2021-04-28 17:13:48.503244 -0400 TCP_ADAPTOR (debug) [C3] pn_raw_connection_take_read_buffers() took 12, freed 0
2021-04-28 17:13:48.503259 -0400 TCP_ADAPTOR (debug) [C3][L28] Granting 12 to pn_raw_connection_give_read_buffers()
2021-04-28 17:13:48.503316 -0400 TCP_ADAPTOR (debug) [C3] qdr_tcp_activate: call pn_raw_connection_wake()
2021-04-28 17:13:48.503393 -0400 TCP_ADAPTOR (trace) [C3][L28][D22] Continuing listener message with 6144 bytes
2021-04-28 17:13:48.503411 -0400 TCP_ADAPTOR (debug) [C3] PN_RAW_CONNECTION_READ Read 6144 bytes. Total read 45488165 bytes
2021-04-28 17:13:48.503423 -0400 TCP_ADAPTOR (debug) [C3][L28] qdr_tcp_push
2021-04-28 17:13:48.503433 -0400 TCP_ADAPTOR (debug) [C3][L27][D25] qdr_tcp_deliver Delivery event
2021-04-28 17:13:48.503445 -0400 TCP_ADAPTOR (info) [C3] EOS
2021-04-28 17:13:48.503458 -0400 TCP_ADAPTOR (debug) [C3] handle_outgoing calling pn_raw_connection_write_close(). rcv_complete:T, send_complete:T
2021-04-28 17:13:48.503521 -0400 TCP_ADAPTOR (debug) [C3][L28] qdr_tcp_offer: NOOP
2021-04-28 17:13:48.503544 -0400 TCP_ADAPTOR (debug) [C3][L28] qdr_tcp_get_credit: NOOP
2021-04-28 17:13:48.503565 -0400 TCP_ADAPTOR (debug) [C3] PN_RAW_CONNECTION_WAKE listener
2021-04-28 17:13:48.503670 -0400 TCP_ADAPTOR (debug) [C3] PN_RAW_CONNECTION_CLOSED_WRITE listener
2021-04-28 17:13:48.503712 -0400 TCP_ADAPTOR (debug) [C3] qdr_tcp_activate: call pn_raw_connection_wake()
2021-04-28 17:13:48.503752 -0400 TCP_ADAPTOR (debug) [C3] PN_RAW_CONNECTION_WAKE listener
2021-04-28 17:13:48.503830 -0400 TCP_ADAPTOR (debug) [C3][L28][D22] qdr_tcp_delivery_update: disp: 38, settled: false
2021-04-28 17:13:48.503852 -0400 TCP_ADAPTOR (debug) [C3][L28][D22] qdr_tcp_delivery_update: disp: 38, settled: false
2021-04-28 17:13:48.503868 -0400 TCP_ADAPTOR (debug) [C3][L28] qdr_tcp_get_credit: NOOP
2021-04-28 17:13:48.503932 -0400 TCP_ADAPTOR (debug) [C3] PN_RAW_CONNECTION_READ listener Event 
2021-04-28 17:13:48.503942 -0400 TCP_ADAPTOR (trace) [C3][L28] handle_incoming PNRC_READ for listener connection. read_closed:F, flow_enabled:T
2021-04-28 17:13:48.503950 -0400 TCP_ADAPTOR (debug) [C3] pn_raw_connection_take_read_buffers() took 0, freed 0
2021-04-28 17:13:48.503957 -0400 TCP_ADAPTOR (debug) [C3][L28] Granting 0 to pn_raw_connection_give_read_buffers()
2021-04-28 17:13:48.503965 -0400 TCP_ADAPTOR (debug) [C3] PN_RAW_CONNECTION_READ Read 0 bytes. Total read 45488165 bytes
2021-04-28 17:13:48.503973 -0400 TCP_ADAPTOR (debug) [C3] PN_RAW_CONNECTION_NEED_READ_BUFFERS listener
2021-04-28 17:13:48.503981 -0400 TCP_ADAPTOR (debug) [C3][L28] Granting 0 to pn_raw_connection_give_read_buffers()
2021-04-28 17:13:48.503988 -0400 TCP_ADAPTOR (trace) [C3][L28] handle_incoming PNRC_NEED_READ_BUFFERS for listener connection. read_closed:F, flow_enabled:T
2021-04-28 17:13:48.503996 -0400 TCP_ADAPTOR (debug) [C3] pn_raw_connection_take_read_buffers() took 0, freed 0
2021-04-28 17:13:48.504003 -0400 TCP_ADAPTOR (debug) [C3][L28] Granting 0 to pn_raw_connection_give_read_buffers()

      Attachments

        1. INTA-tcplog.conf
          0.9 kB
          Charles E. Rolke
        2. INTB-tcplog.conf
          1 kB
          Charles E. Rolke

        Activity

          People

            Unassigned Unassigned
            chug Charles E. Rolke
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved: