Ganesh Murthy created PROTON-2680:
-------------------------------------
Summary: [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
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
