[
https://issues.apache.org/jira/browse/PROTON-2680?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17683468#comment-17683468
]
Ganesh Murthy commented on PROTON-2680:
---------------------------------------
Comment Clifford Jansen -
This looks to me like 2 bugs. The first might be cascading to the one you are
asking about.
The "other" bug is a PN_RAW_CONNECTION_READ with 0 bytes, which appears to
contradict the docs. It looks like this might result in the raw connection
being in some state that prevents the detected PN_RAW_CONNECTION_CLOSED_READ to
progress towards a disconnect.
It should suffice to raise a single Jira.
> [proton-c] PN_RAW_CONNECTION_DISCONNECTED event does not show up when client
> is disconnected
> ---------------------------------------------------------------------------------------------
>
> Key: PROTON-2680
> URL: https://issues.apache.org/jira/browse/PROTON-2680
> Project: Qpid Proton
> Issue Type: Bug
> Components: proton-c
> Reporter: Ganesh Murthy
> Priority: Major
>
> Steps to reproduce
> Start the skupper-router with the following config -
> {noformat}
> router {
> mode: standalone
> }
> listener {
> host: 0.0.0.0
> port: amqp
> authenticatePeer: no
> saslMechanisms: ANONYMOUS
> }
> tcpConnector {
> name: echo-1
> host: 10.108.50.177
> port: 9090
> address: echo
> }
> tcpConnector {
> name: echo-2
> host: 10.108.50.177
> port: 9090
> address: echo
> }
> tcpListener {
> host: 0.0.0.0
> port: 9000
> address: echo
> }
> log {
> module: DEFAULT
> enable: trace+
> outputFile: tcp.log
> } {noformat}
>
> Note that the ip address in the host field of the tcpConnector is bogus.
> Now connect a curl client to the tcpListener port -
> {noformat}
> curl http://localhost:9000/api {noformat}
>
> The curl client will hang. Terminate the curl client and look in the tcp.log
> for logged proton events - the PN_RAW_CONNECTION_DISCONNECTED event will be
> missing on connection C2
> Here is the full log of the relevant client connection
>
> {noformat}
> 2023-02-01 16:51:57.069705 -0500 ROUTER_CORE (info) [C2] Connection Opened:
> dir=in host=127.0.0.1:35348 encrypted=no auth=no user=
> container_id=TcpAdaptor props={:"qd.adaptor"="tcp"}
> 2023-02-01 16:51:57.069793 -0500 ROUTER_CORE (trace) Core action
> 'connection_opened'
> 2023-02-01 16:51:57.069986 -0500 TCP_ADAPTOR (info) [C2]
> PN_RAW_CONNECTION_CONNECTED Listener ingress accepted to 0.0.0.0:9000 from
> 127.0.0.1:35348 (global_id=127.0.0.1:35348)
> 2023-02-01 16:51:57.070015 -0500 ROUTER_CORE (trace) Core action
> 'link_first_attach'
> 2023-02-01 16:51:57.070098 -0500 TCP_ADAPTOR (debug) [C2]
> PN_RAW_CONNECTION_NEED_WRITE_BUFFERS listener
> 2023-02-01 16:51:57.070148 -0500 TCP_ADAPTOR (debug) [C2]
> PN_RAW_CONNECTION_NEED_READ_BUFFERS listener
> 2023-02-01 16:51:57.070171 -0500 ROUTER_CORE (info) [C2][L4] Link attached:
> dir=out source={(dyn)<none> expire:link} target={<none> expire:link}
> 2023-02-01 16:51:57.070222 -0500 TCP_ADAPTOR (debug) [C2]
> qdr_tcp_activate_CT: call pn_raw_connection_wake()
> 2023-02-01 16:51:57.070246 -0500 ROUTER_CORE (trace) Core action
> 'link_first_attach'
> 2023-02-01 16:51:57.070273 -0500 TCP_ADAPTOR (debug) [C2][L4] (listener
> outgoing) qdr_tcp_second_attach
> 2023-02-01 16:51:57.070347 -0500 DEFAULT (trace) Parse tree search for 'echo'
> 2023-02-01 16:51:57.070376 -0500 TCP_ADAPTOR (trace) [C2][L5] handle_incoming
> qdr_tcp_second_attach for listener connection. read_closed:F, flow_enabled:F
> 2023-02-01 16:51:57.070404 -0500 DEFAULT (trace) Parse tree match not found
> 2023-02-01 16:51:57.070425 -0500 TCP_ADAPTOR (debug) [C2][L5] Waiting for
> credit before initiating listener ingress stream message, returning
> 2023-02-01 16:51:57.070456 -0500 TCP_ADAPTOR (debug) [C2][L4]
> qdr_tcp_get_credit: NOOP
> 2023-02-01 16:51:57.070517 -0500 TCP_ADAPTOR (trace) Listener
> tcpListener/0.0.0.0:9000 (0.0.0.0:9000) service address echo consumer count
> updates: local=1 in-process=0 remote=0
> 2023-02-01 16:51:57.070553 -0500 ROUTER_CORE (info) [C2][L5] Link attached:
> dir=in source={<none> expire:link} target={echo expire:link}
> 2023-02-01 16:51:57.070583 -0500 ROUTER_CORE (trace) Core action
> 'add_tcp_connection'
> 2023-02-01 16:51:57.070606 -0500 TCP_ADAPTOR (debug) [C2]
> PN_RAW_CONNECTION_WAKE listener
> 2023-02-01 16:51:57.070646 -0500 TCP_ADAPTOR (debug) [C2]
> qdr_add_tcp_connection_CT 0.0.0.0:9000 (1)
> 2023-02-01 16:51:57.070673 -0500 TCP_ADAPTOR (debug) [C2][L4] qdr_tcp_flow:
> Flow enabled, credit=250
> 2023-02-01 16:51:57.070722 -0500 TCP_ADAPTOR (debug) [C2]
> qdr_tcp_activate_CT: call pn_raw_connection_wake()
> 2023-02-01 16:51:57.070774 -0500 ROUTER_CORE (trace) Core action 'link_flow'
> 2023-02-01 16:51:57.070800 -0500 TCP_ADAPTOR (trace) [C2][L5] handle_incoming
> qdr_tcp_flow for listener connection. read_closed:F, flow_enabled:T
> 2023-02-01 16:51:57.070831 -0500 TCP_ADAPTOR (debug) [C2]
> handle_incoming_raw_read() returning with result=0
> 2023-02-01 16:51:57.071258 -0500 TCP_ADAPTOR (debug) [C2][L5] Initiating
> listener (ingress) stream incoming link for listener connection to: echo
> reply: amqp:/_topo/0/QDR.A/temp.rr__pKcuMowq3o4
> 2023-02-01 16:51:57.071468 -0500 ROUTER_CORE (debug) [C2][L5][D1] Delivery
> created qdr_link_deliver
> 2023-02-01 16:51:57.071513 -0500 ROUTER_CORE (debug) [C2][L5][D1] Delivery
> incref: rc:1 qdr_link_deliver - newly created delivery, add to action list
> 2023-02-01 16:51:57.071535 -0500 ROUTER_CORE (debug) [C2][L5][D1] Delivery
> incref: rc:2 qdr_link_deliver - protect returned value
> 2023-02-01 16:51:57.071559 -0500 TCP_ADAPTOR (debug) [C2][L5][D1] Initiating
> listener side empty incoming stream message
> 2023-02-01 16:51:57.071580 -0500 ROUTER_CORE (trace) Core action
> 'link_deliver'
> 2023-02-01 16:51:57.071940 -0500 ROUTER_CORE (debug) [C1][L3][D2] Delivery
> created qdr_forward_new_delivery_CT
> 2023-02-01 16:51:57.071989 -0500 ROUTER_CORE (trace) [C2][L5][D1] :in
> qdr_delivery_link_peers_CT out: [C1][L3][D2]
> 2023-02-01 16:51:57.072039 -0500 ROUTER_CORE (debug) [C1][L3][D2] Delivery
> incref: rc:1 qdr_delivery_link_peers_CT - linked to peer (out delivery)
> 2023-02-01 16:51:57.072151 -0500 ROUTER_CORE (debug) [C2][L5][D1] Delivery
> incref: rc:3 qdr_delivery_link_peers_CT - linked to peer (in delivery)
> 2023-02-01 16:51:57.072187 -0500 TCP_ADAPTOR (debug) [C2]
> grant_read_buffers(handle_incoming) granted 16 read buffers to proton raw api
> 2023-02-01 16:51:57.072256 -0500 TCP_ADAPTOR (debug) [C2] handle_incoming
> call to handle_incoming_raw_read returned count=0
> 2023-02-01 16:51:57.072295 -0500 TCP_ADAPTOR (debug) [C2][L5]
> qdr_tcp_get_credit: NOOP
> 2023-02-01 16:51:57.072338 -0500 ROUTER_CORE (debug) [C1][L3][D2] Delivery
> incref: rc:2 qdr_forward_deliver_CT - add to undelivered list
> 2023-02-01 16:51:57.072384 -0500 TCP_ADAPTOR (debug) [C2]
> PN_RAW_CONNECTION_WAKE listener
> 2023-02-01 16:51:57.072419 -0500 ROUTER_CORE (debug) [C2][L5][D1] Delivery
> transfer: qdr_link_forward_CT: action-list -> unsettled-list
> 2023-02-01 16:51:57.072471 -0500 TCP_ADAPTOR (trace) [C2][L5] handle_incoming
> PNRC_READ for listener connection. read_closed:F, flow_enabled:T
> 2023-02-01 16:51:57.072504 -0500 TCP_ADAPTOR (debug) [C1]
> qdr_tcp_activate_CT: schedule activate_timer
> 2023-02-01 16:51:57.072543 -0500 TCP_ADAPTOR (debug) [C2]
> pn_raw_connection_take_read_buffers() took buffer with 81 bytes
> 2023-02-01 16:51:57.072589 -0500 TCP_ADAPTOR (debug) [C1] on_activate
> 2023-02-01 16:51:57.072650 -0500 TCP_ADAPTOR (debug) [C2]
> handle_incoming_raw_read() returning with result=81
> 2023-02-01 16:51:57.072679 -0500 TCP_ADAPTOR (debug) [C1][L3] qdr_tcp_push
> 2023-02-01 16:51:57.072717 -0500 TCP_ADAPTOR (debug) [C2]
> grant_read_buffers(handle_incoming) granted 1 read buffers to proton raw api
> 2023-02-01 16:51:57.072757 -0500 ROUTER_CORE (debug) [C1][L3][D2] Delivery
> incref: rc:3 qdr_link_process_deliveries - holding the undelivered
> delivery locally
> 2023-02-01 16:51:57.072793 -0500 TCP_ADAPTOR (debug) [C1][L3][D2]
> qdr_tcp_deliver Delivery event
> 2023-02-01 16:51:57.072816 -0500 TCP_ADAPTOR (debug) [C1][L3][D2] tcp_adaptor
> delivery arrived on egress dispatcher connection, initiating actual egress
> connection
> 2023-02-01 16:51:57.072838 -0500 TCP_ADAPTOR (trace) [C2][L5][D1] Continuing
> listener message with 81 bytes
> 2023-02-01 16:51:57.072934 -0500 ROUTER_CORE (debug) [C2][L5][D1] Delivery
> incref: rc:4 qdr_delivery_continue - add to action list
> 2023-02-01 16:51:57.072991 -0500 TCP_ADAPTOR (debug) [C2]
> PN_RAW_CONNECTION_READ Read 81 bytes. Total read 81 bytes, Total encrypted
> bytes=0
> 2023-02-01 16:51:57.073023 -0500 ROUTER_CORE (trace) Core action
> 'delivery_continue'
> 2023-02-01 16:51:57.073068 -0500 ROUTER_CORE (debug) [C2][L5][D1] Delivery
> decref_CT: rc:3 qdr_delivery_continue_CT - remove from action 2
> 2023-02-01 16:51:59.218802 -0500 TCP_ADAPTOR (trace) [C2][L5] handle_incoming
> PNRC_READ for listener connection. read_closed:F, flow_enabled:T
> 2023-02-01 16:51:59.218995 -0500 TCP_ADAPTOR (debug) [C2]
> handle_incoming_raw_read() returning with result=0
> 2023-02-01 16:51:59.219077 -0500 TCP_ADAPTOR (debug) [C2]
> grant_read_buffers(handle_incoming) granted 0 read buffers to proton raw api
> 2023-02-01 16:51:59.219169 -0500 TCP_ADAPTOR (debug) [C2] handle_incoming
> call to handle_incoming_raw_read returned count=0
> 2023-02-01 16:51:59.219245 -0500 TCP_ADAPTOR (debug) [C2]
> PN_RAW_CONNECTION_READ Read 0 bytes. Total read 81 bytes, Total encrypted
> bytes=0
> 2023-02-01 16:51:59.219342 -0500 TCP_ADAPTOR (trace) [C2][L5] handle_incoming
> PNRC_CLOSED_READ for listener connection. read_closed:T, flow_enabled:T
> 2023-02-01 16:51:59.219476 -0500 TCP_ADAPTOR (debug) [C2]
> handle_incoming_raw_read() returning with result=0
> 2023-02-01 16:51:59.219540 -0500 TCP_ADAPTOR (debug) [C2] handle_incoming
> call to handle_incoming_raw_read returned count=0
> 2023-02-01 16:51:59.219602 -0500 TCP_ADAPTOR (debug) [C2][L5][D1] close
> listener in_dlv_stream delivery, setting receive_complete=true
> 2023-02-01 16:51:59.219684 -0500 ROUTER_CORE (debug) [C2][L5][D1] Delivery
> incref: rc:4 qdr_delivery_continue - add to action list
> 2023-02-01 16:51:59.219745 -0500 TCP_ADAPTOR (debug) [C2]
> PN_RAW_CONNECTION_CLOSED_READ listener
> 2023-02-01 16:51:59.219837 -0500 ROUTER_CORE (trace) Core action
> 'delivery_continue'
> 2023-02-01 16:51:59.220029 -0500 ROUTER_CORE (debug) [C2][L5][D1] Delivery
> decref_CT: rc:3 qdr_delivery_continue_CT - remove from action 2 {noformat}
>
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@qpid.apache.org
For additional commands, e-mail: dev-h...@qpid.apache.org
