[PROTON-2680] [proton-c] PN_RAW_CONNECTION_DISCONNECTED event does not show up when client is disconnected - ASF JIRA

XML

Word

Printable

JSON

Details

Type: Bug
Status: Open
Priority: Major
Resolution: Unresolved
Affects Version/s: None
Fix Version/s: None
Component/s: proton-c
Labels:
None

Description

Steps to reproduce

Start the skupper-router with the following config -

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
}

Note that the ip address in the host field of the tcpConnector is bogus.

Now connect a curl client to the tcpListener port -

curl http://localhost:9000/api

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

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

Attachments

Activity

People

Assignee:: Clifford Jansen

Reporter:: Ganesh Murthy

Votes:: 0 Vote for this issue

Watchers:: 2 Start watching this issue

Dates

Created:: 02/Feb/23 15:30

Updated:: 15/Aug/23 05:54