[
https://issues.apache.org/jira/browse/DISPATCH-1972?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17294520#comment-17294520
]
Charles E. Rolke commented on DISPATCH-1972:
--------------------------------------------
Trying to isolate the pn assertion: is it a dispatch or proton problem?
h4. Source code
Running a debug build of
Proton git branch master @ 2381e1f53.
Dispatch git branch crolke-D-1972-leaks @ d141d64d
Where the git branch is available at
[https://github.com/ChugR/qpid-dispatch.git]
h4. Router config
The test case is to run qpid dispatch with this config file
{code:java}
router {
mode: interior
id: INTA
workerThreads: 6
debugDumpFile: INTA-debug-dump.txt
}
listener {
port: amqp
host: 0.0.0.0
saslMechanisms: ANONYMOUS
idleTimeoutSeconds: 120
authenticatePeer: no
role: normal
}
tcpListener {
host: 0.0.0.0
port: 5202
address: iperf3
siteId: mySite
}
tcpConnector {
host: 127.0.0.1
port: 5201
address: iperf3
siteId: mySite
}
log {
module: DEFAULT
enable: info+
outputFile: INTA.log
}
log {
module: TCP_ADAPTOR
enable: trace+
outputFile: INTA.log
}
{code}
h4. Test code
Then a test loop starts a series of echo server and clients. The server exits
after receiving 200k bytes and the clients try to send a megabyte. Both the
server and client exit with errors and the loop starts again. Eventually the
router crashes. If you run this yourself you have to watch for when the router
goes down and stop the loop manually.
One characteristic of this test is that dispatch accepts an incoming connection
and opens an outgoing connection as fast as it can.
{code:bash}
for (( ; ; ))
do
ECHO_SERVER --port 5201 --log --echo 200000 &
ECHO_CLIENT --host 127.0.0.1 --port 5202 --log --size 10000000
done
{code}
h4. Log analysis
Note the test finally failed on pass 750 or so. The raw router log is over 300
megabytes. This analysis holds curated results only.
Gathering log snippets and greps reveals that the raw connection proton
complains about in the assert appears to be properly closed by dispatch.
{code:java}
Router using/freeing pn raw connection 0x7ff43c197c50
Several cycles of using the pn_raw for ingress and egress
It appears to be properly disconnected when at the last usage the pn assertion
is raised
2021-03-02 17:20:04.637286 -0500 TCP_ADAPTOR (info) New ingress {bind
conn=0x7ff44421cd90 pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:04.637390 -0500 TCP_ADAPTOR (info) [C1530] ingress accept
{conn=0x7ff44421cd90 pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:04.762188 -0500 TCP_ADAPTOR (info) [C1530]
PN_RAW_CONNECTION_DISCONNECTED {unbind conn=0x7ff44421cd90
pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:06.038976 -0500 TCP_ADAPTOR (info) New ingress {bind
conn=0x7ff43c129dd0 pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:06.039090 -0500 TCP_ADAPTOR (info) [C1536] ingress accept
{conn=0x7ff43c129dd0 pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:06.149257 -0500 TCP_ADAPTOR (info) [C1536]
PN_RAW_CONNECTION_DISCONNECTED {unbind conn=0x7ff43c129dd0
pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:06.461759 -0500 TCP_ADAPTOR (info) New ingress {bind
conn=0x2582f10 pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:06.461865 -0500 TCP_ADAPTOR (info) [C1538] ingress accept
{conn=0x2582f10 pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:06.582302 -0500 TCP_ADAPTOR (info) [C1538]
PN_RAW_CONNECTION_DISCONNECTED {unbind conn=0x2582f10
pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:08.955028 -0500 TCP_ADAPTOR (info) [C1549] New egress {bind
conn=0x7ff43c124290 pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:09.075582 -0500 TCP_ADAPTOR (info) [C1549]
PN_RAW_CONNECTION_DISCONNECTED {unbind conn=0x7ff43c124290
pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:09.420997 -0500 TCP_ADAPTOR (info) [C1551] New egress {bind
conn=0x7ff434010690 pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:09.507829 -0500 TCP_ADAPTOR (info) [C1551]
PN_RAW_CONNECTION_DISCONNECTED {unbind conn=0x7ff434010690
pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:09.829645 -0500 TCP_ADAPTOR (info) [C1553] New egress {bind
conn=0x7ff44421c290 pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:09.938048 -0500 TCP_ADAPTOR (info) [C1553]
PN_RAW_CONNECTION_DISCONNECTED {unbind conn=0x7ff44421c290
pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:10.697508 -0500 TCP_ADAPTOR (info) New ingress {bind
conn=0x2502290 pn_raw_conn=0x7ff43c197c50}
----
#0 0x00007ff466a317d5 in raise () from /lib64/libc.so.6
#1 0x00007ff466a1a895 in abort () from /lib64/libc.so.6
#2 0x00007ff466a1a769 in __assert_fail_base.cold () from /lib64/libc.so.6
#3 0x00007ff466a29e86 in __assert_fail () from /lib64/libc.so.6
#4 0x00007ff467028d90 in pni_raw_new_state (conn=0x7ff43c197c50,
event=conn_connected) at
/home/chug/git/qpid-proton/c/src/proactor/raw_connection.c:103
#5 0x00007ff46702a404 in pni_raw_connected (conn=0x7ff43c197c50) at
/home/chug/git/qpid-proton/c/src/proactor/raw_connection.c:461
#6 0x00007ff467026b3d in praw_connection_connected_lh (prc=0x7ff43c197b90) at
/home/chug/git/qpid-proton/c/src/proactor/epoll_raw_connection.c:82
#7 0x00007ff4670271bd in pn_listener_raw_accept (l=0x24f29d0,
rc=0x7ff43c197c50) at
/home/chug/git/qpid-proton/c/src/proactor/epoll_raw_connection.c:239
#8 0x00007ff4670d3be2 in qdr_tcp_connection_ingress (listener=0x24f2950) at
/home/chug/git/qpid-dispatch/src/adaptors/tcp_adaptor.c:727
#9 0x00007ff4670d45e5 in handle_listener_event (e=0x2423dc0,
qd_server=0x22c0810, context=0x24f2950) at
/home/chug/git/qpid-dispatch/src/adaptors/tcp_adaptor.c:897
#10 0x00007ff46714cdb3 in handle_event_with_context (e=0x2423dc0,
qd_server=0x22c0810, context=0x24f2950) at
/home/chug/git/qpid-dispatch/src/server.c:804
#11 0x00007ff46714ce2d in do_handle_listener (e=0x2423dc0, qd_server=0x22c0810)
at /home/chug/git/qpid-dispatch/src/server.c:815
#12 0x00007ff46714d7f3 in handle (qd_server=0x22c0810, e=0x2423dc0,
pn_conn=0x0, ctx=0x0) at /home/chug/git/qpid-dispatch/src/server.c:1014
#13 0x00007ff46714de34 in thread_run (arg=0x22c0810) at
/home/chug/git/qpid-dispatch/src/server.c:1122
#14 0x00007ff467100738 in _thread_init (arg=0x23d4b50) at
/home/chug/git/qpid-dispatch/src/posix/threading.c:172
#15 0x00007ff466fce432 in start_thread (arg=<optimized out>) at
pthread_create.c:477
#16 0x00007ff466af66d3 in clone () from /lib64/libc.so.6
-----
Usage of router connection C1553
2021-03-02 17:20:09.911345 -0500 TCP_ADAPTOR (debug) [C1553]
PN_RAW_CONNECTION_WRITTEN Wrote 8192 bytes. Total written 1990656 bytes
2021-03-02 17:20:09.911357 -0500 TCP_ADAPTOR (debug) [C1553] qdr_tcp_activate:
waking raw connection
2021-03-02 17:20:09.911375 -0500 TCP_ADAPTOR (debug) [C1553][L3105] qdr_tcp_push
2021-03-02 17:20:09.911387 -0500 TCP_ADAPTOR (debug) [C1553][L3104][D3102]
qdr_tcp_deliver Delivery event
2021-03-02 17:20:09.911396 -0500 TCP_ADAPTOR (debug) [C1553] Writing 2048 bytes
2021-03-02 17:20:09.911406 -0500 TCP_ADAPTOR (debug) [C1553] Writing 2048 bytes
2021-03-02 17:20:09.911421 -0500 TCP_ADAPTOR (debug) [C1553] Writing 2048 bytes
2021-03-02 17:20:09.911439 -0500 TCP_ADAPTOR (debug) [C1553] Writing 2048 bytes
2021-03-02 17:20:09.911490 -0500 TCP_ADAPTOR (debug) [C1553] Writing 0 bytes
2021-03-02 17:20:09.911500 -0500 TCP_ADAPTOR (debug) [C1553][L3105]
qdr_tcp_get_credit: NOOP
2021-03-02 17:20:09.911510 -0500 TCP_ADAPTOR (debug) [C1553]
PN_RAW_CONNECTION_WAKE
2021-03-02 17:20:09.911716 -0500 TCP_ADAPTOR (debug) [C1553] qdr_tcp_activate:
waking raw connection
2021-03-02 17:20:09.911800 -0500 TCP_ADAPTOR (debug) [C1553]
PN_RAW_CONNECTION_WAKE
2021-03-02 17:20:09.911846 -0500 TCP_ADAPTOR (debug) [C1553][L3105] qdr_tcp_push
2021-03-02 17:20:09.911871 -0500 TCP_ADAPTOR (debug) [C1553][L3104][D3102]
qdr_tcp_deliver Delivery event
2021-03-02 17:20:09.911880 -0500 TCP_ADAPTOR (debug) [C1553] Writing 0 bytes
2021-03-02 17:20:09.911890 -0500 TCP_ADAPTOR (debug) [C1553][L3105]
qdr_tcp_get_credit: NOOP
2021-03-02 17:20:09.911904 -0500 TCP_ADAPTOR (debug) [C1553] qdr_tcp_activate:
waking raw connection
2021-03-02 17:20:09.911950 -0500 TCP_ADAPTOR (debug) [C1553]
PN_RAW_CONNECTION_WRITTEN Wrote 8192 bytes. Total written 1998848 bytes
2021-03-02 17:20:09.911963 -0500 TCP_ADAPTOR (debug) [C1553]
PN_RAW_CONNECTION_WAKE
2021-03-02 17:20:09.911973 -0500 TCP_ADAPTOR (debug) [C1553]
PN_RAW_CONNECTION_NEED_WRITE_BUFFERS
2021-03-02 17:20:09.911983 -0500 TCP_ADAPTOR (debug) [C1553] Writing 2048 bytes
2021-03-02 17:20:09.911993 -0500 TCP_ADAPTOR (debug) [C1553] Writing 2048 bytes
2021-03-02 17:20:09.912002 -0500 TCP_ADAPTOR (debug) [C1553] Writing 2048 bytes
2021-03-02 17:20:09.912011 -0500 TCP_ADAPTOR (debug) [C1553] Writing 2048 bytes
2021-03-02 17:20:09.912047 -0500 TCP_ADAPTOR (debug) [C1553] Writing 0 bytes
2021-03-02 17:20:09.937639 -0500 TCP_ADAPTOR (debug) [C1553]
PN_RAW_CONNECTION_CLOSED_READ
2021-03-02 17:20:09.937698 -0500 TCP_ADAPTOR (debug) [C1553] Took 0 read buffers
2021-03-02 17:20:09.937718 -0500 TCP_ADAPTOR (debug) [C1553] Freed 16 read
buffers
2021-03-02 17:20:09.937750 -0500 TCP_ADAPTOR (debug) [C1553][L3105] Continuing
message with 0 bytes
2021-03-02 17:20:09.937771 -0500 TCP_ADAPTOR (debug) [C1553]
PN_RAW_CONNECTION_CLOSED_WRITE
2021-03-02 17:20:09.937787 -0500 TCP_ADAPTOR (debug) [C1553] Took 0 read buffers
2021-03-02 17:20:09.937801 -0500 TCP_ADAPTOR (debug) [C1553] Freed 0 read
buffers
2021-03-02 17:20:09.937824 -0500 TCP_ADAPTOR (debug) [C1553][L3105] Continuing
message with 0 bytes
2021-03-02 17:20:09.937850 -0500 TCP_ADAPTOR (debug) [C1553]
PN_RAW_CONNECTION_READ Read 0 bytes. Total read 200192 bytes
2021-03-02 17:20:09.937906 -0500 TCP_ADAPTOR (debug) [C1553]
PN_RAW_CONNECTION_WRITTEN Wrote 8192 bytes. Total written 2007040 bytes
2021-03-02 17:20:09.938048 -0500 TCP_ADAPTOR (info) [C1553]
PN_RAW_CONNECTION_DISCONNECTED {unbind conn=0x7ff44421c290
pn_raw_conn=0x7ff43c197c50}
2021-03-02 17:20:09.938071 -0500 TCP_ADAPTOR (debug) [C1553][L3105]
handle_disconnected - close instream
2021-03-02 17:20:09.938095 -0500 TCP_ADAPTOR (debug) [C1553][L3104]
handle_disconnected close outstream
2021-03-02 17:20:09.938135 -0500 TCP_ADAPTOR (debug) [C1553][L3105]
handle_disconnected - detach incoming
2021-03-02 17:20:09.938161 -0500 TCP_ADAPTOR (debug) [C1553][L3104]
handle_disconnected - detach outgoing
2021-03-02 17:20:09.938274 -0500 ROUTER_CORE (info) [C1553][L3105] Link lost:
del=1 presett=1 psdrop=0 acc=0 rej=0 rel=0 mod=0 delay1=0 delay10=0 blocked=no
2021-03-02 17:20:09.938362 -0500 ROUTER_CORE (info) [C1553][L3104] Link lost:
del=0 presett=0 psdrop=0 acc=0 rej=0 rel=0 mod=0 delay1=0 delay10=0 blocked=no
2021-03-02 17:20:09.938380 -0500 ROUTER_CORE (info) [C1553] Connection Closed
2021-03-02 17:20:09.938497 -0500 TCP_ADAPTOR (debug) [C1553]
qdr_del_tcp_connection_CT 127.0.0.1:5201 deleted. bytes_in=200192,
bytes_out=2007040, opened_time=356, last_in_time=356, last_out_time=356.
Connections remaining 1
{code}
> TCP adaptor leaks messages and buffers when server closes connection
> --------------------------------------------------------------------
>
> Key: DISPATCH-1972
> URL: https://issues.apache.org/jira/browse/DISPATCH-1972
> Project: Qpid Dispatch
> Issue Type: Bug
> Components: Protocol Adaptors
> Affects Versions: 1.15.0
> Reporter: Charles E. Rolke
> Priority: Major
>
> Following on to DISPATCH-1968 the TCP adaptor sometimes does not clean up
> connections, messages, deliveries, and buffers when the server-side
> connection closes first while the client is sending and receiving.
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
