XIO complains about leaking user object (which is no user object)

[Christian Tinnefeld]

Dear Accelio-Team,

Sporadically xio complains about leaking user object of type struct xio_context, although the object has not been created in the user space. There are two places in my code where I call "xio_context_create" both are succeeded by a print out (..."Context pointer: %p"...) of the address. Please note that at the end of the attached log the address is printed of the supposedly leaking xio object ( 0x61500000d280 ), and that this address can also be found associated with the client session (" [2015/04/28-10:41:07.171155] xio_session_client.c:1019 [DEBUG] - xio_connect: session:0x61400001e640, connection:0x616000002d80, ctx:0x61500000d280, nexus:0x61400001e440 "), however it differs from the context object created in user space (" [XIO_CLIENT_PORTAL] Context pointer: 0x626000002310 ).

My setup: Ubuntu 14.04, Accelio for_next branch, commit a5ab248, executed via TCP stack on localhost

[ RUN ] TestNetPortalFixture/0.SendSyncRequest
[2015/04/28-10:41:07.170675] xio_netlink.c:156 [DEBUG] - statistics monitoring disabled. not privileged user
[XIO_SERVER_PORTAL] Context pointer: 0x61f00000bb48
[2015/04/28-10:41:07.170703] xio_server.c:322 [TRACE] - bind to tcp://127.0.0.1:10010
[2015/04/28-10:41:07.170730] xio_mempool.c:491 [DEBUG] - mempool: using huge pages allocator
[2015/04/28-10:41:07.170754] xio_tcp_management.c:882 [TRACE] - xio_tcp_open: [new] handle:0x62900005a200
[2015/04/28-10:41:07.170759] xio_nexus.c:2004 [TRACE] - nexus: [new] nexus:0x61400000de40, transport_hndl:0x62900005a200
[2015/04/28-10:41:07.170791] xio_tcp_management.c:1275 [DEBUG] - listen on [tcp://127.0.0.1:10010] src_port:10010
[XIO_SERVER_PORTAL] Open: tcp://127.0.0.1:10010
[2015/04/28-10:41:07.170995] xio_netlink.c:156 [DEBUG] - statistics monitoring disabled. not privileged user
[XIO_CLIENT_PORTAL] Context pointer: 0x626000002310
[2015/04/28-10:41:07.171040] xio_mempool.c:491 [DEBUG] - mempool: using huge pages allocator
[2015/04/28-10:41:07.171057] xio_tcp_management.c:882 [TRACE] - xio_tcp_open: [new] handle:0x629000073200
[2015/04/28-10:41:07.171061] xio_nexus.c:2004 [TRACE] - nexus: [new] nexus:0x61400001e440, transport_hndl:0x629000073200
[2015/04/28-10:41:07.171071] xio_nexus.c:2094 [TRACE] - xio_nexus_connect: nexus:0x61400001e440, rdma_hndl:0x629000073200, portal:tcp://127.0.0.1:10010
[2015/04/28-10:41:07.171155] xio_session_client.c:1019 [DEBUG] - xio_connect: session:0x61400001e640, connection:0x616000002d80, ctx:0x61500000d280, nexus:0x61400001e440
[2015/04/28-10:41:07.171533] xio_nexus.c:1731 [DEBUG] - nexus: [notification] - transport established. nexus:0x61400001e440, transport:0x629000073200
[2015/04/28-10:41:07.171576] xio_tcp_management.c:882 [TRACE] - xio_tcp_open: [new] handle:0x629000069200
[2015/04/28-10:41:07.171600] xio_nexus.c:384 [TRACE] - send setup request
[2015/04/28-10:41:07.171608] xio_nexus.c:426 [TRACE] - xio_nexus_send_setup_req: nexus:0x61400001e440, rdma_hndl:0x629000073200
[2015/04/28-10:41:07.171611] xio_tcp_datapath.c:231 [DEBUG] - xio_tcp_send_setup_req
[2015/04/28-10:41:07.171620] xio_tcp_datapath.c:245 [TRACE] - tcp send setup request
[2015/04/28-10:41:07.171611] xio_nexus.c:1726 [DEBUG] - nexus: [notification] - new transport. nexus:0x61400000de40, transport:0x62900005a200
[2015/04/28-10:41:07.171750] xio_nexus.c:1345 [TRACE] - nexus: [new] ptr:0x61400000da40, transport_hndl:0x629000069200
[2015/04/28-10:41:07.171771] xio_nexus.c:1387 [TRACE] - xio_nexus_on_new_transport: nexus:0x61400000da40, trans_hndl:0x629000069200
[2015/04/28-10:41:07.171776] xio_server.c:278 [DEBUG] - server: [notification] - new connection. server:0x610000017340, nexus:0x61400000de40
[2015/04/28-10:41:07.171785] xio_tcp_management.c:680 [TRACE] - tcp transport: [accept] handle:0x629000069200
[2015/04/28-10:41:07.171790] xio_nexus.c:1731 [DEBUG] - nexus: [notification] - transport established. nexus:0x61400000da40, transport:0x629000069200
[2015/04/28-10:41:07.171798] xio_tcp_datapath.c:315 [DEBUG] - xio_tcp_on_setup_msg
[2015/04/28-10:41:07.171802] xio_nexus.c:527 [TRACE] - receiving setup request
[2015/04/28-10:41:07.172030] xio_mem.c:98 [WARN ] - huge pages allocation failed, allocating regular pages
[2015/04/28-10:41:07.172041] xio_mem.c:101 [DEBUG] - mmap rdma pool sz:6291456 failed (errno=12 Cannot allocate memory)
[2015/04/28-10:41:07.173280] xio_tcp_management.c:2159 [DEBUG] - pool buf:0x7ff2883f3000
[2015/04/28-10:41:07.173324] xio_nexus.c:597 [TRACE] - xio_nexus_on_recv_setup_req: nexus:0x61400000da40, trans_hndl:0x629000069200
[2015/04/28-10:41:07.173329] xio_tcp_datapath.c:275 [DEBUG] - xio_tcp_send_setup_rsp
[2015/04/28-10:41:07.173333] xio_tcp_datapath.c:288 [TRACE] - tcp send setup response
[2015/04/28-10:41:07.173422] xio_tcp_datapath.c:315 [DEBUG] - xio_tcp_on_setup_msg
[2015/04/28-10:41:07.173432] xio_nexus.c:622 [TRACE] - receiving setup response
[2015/04/28-10:41:07.173435] xio_nexus.c:662 [TRACE] - xio_nexus_on_recv_setup_rsp: nexus:0x61400001e440, trans_hndl:0x629000073200
[2015/04/28-10:41:07.173731] xio_mem.c:98 [WARN ] - huge pages allocation failed, allocating regular pages
[2015/04/28-10:41:07.173740] xio_mem.c:101 [DEBUG] - mmap rdma pool sz:6291456 failed (errno=12 Cannot allocate memory)
[2015/04/28-10:41:07.175212] xio_tcp_management.c:2159 [DEBUG] - pool buf:0x7ff287d9e000
[2015/04/28-10:41:07.175259] xio_session_client.c:790 [DEBUG] - session: [notification] - nexus established. session:0x61400001e640, nexus:0x61400001e440
[2015/04/28-10:41:07.175370] xio_server.c:271 [TRACE] - server: [notification] - new message. server:0x610000017340, nexus:0x61400000da40
[2015/04/28-10:41:07.175392] xio_server.c:148 [DEBUG] - server [new session]: server:0x610000017340, session:0x61400000d840, nexus:0x61400000da40 ,session_id:9
[2015/04/28-10:41:07.175433] xio_session_server.c:437 [TRACE] - session state changed to ONLINE. session:0x61400000d840
[XIO_SERVER_PORTAL] On New Session: 127.0.0.1:46783
[XIO_SERVER_PORTAL] On Session: new connection. session:0x61400000d840, connection:0x61600002e880, reason: Success
[2015/04/28-10:41:07.175526] xio_session_client.c:503 [DEBUG] - task recycled
[2015/04/28-10:41:07.175544] xio_session_client.c:517 [TRACE] - session state is now ONLINE. session:0x61400001e640
[2015/04/28-10:41:07.175549] xio_connection.c:2579 [DEBUG] - recv hello response. session:0x61400001e640, connection:0x616000002d80
[XIO_CLIENT_PORTAL] On Session: connection established. session:0x61400001e640, connection:0x616000002d80, reason: Success
[2015/04/28-10:41:07.175558] xio_session_server.c:633 [DEBUG] - session: [notification] - connection established. session:0x61400000d840, nexus:0x61400000da40
[2015/04/28-10:41:07.175567] xio_session_server.c:550 [TRACE] - got session setup response comp. session:0x61400000d840, connection:0x61600002e880
[2015/04/28-10:41:07.175572] xio_session_server.c:558 [DEBUG] - task recycled
[2015/04/28-10:41:07.175849] xio_connection.c:1723 [DEBUG] - xio_disconnect. session:0x61400001e640 connection:0x616000002d80 state:ONLINE
[2015/04/28-10:41:07.175930] xio_connection.c:1578 [DEBUG] - send fin request. session:0x61400001e640, connection:0x616000002d80
[XIO_CLIENT_PORTAL] On Session: connection closed. session:0x61400001e640, connection:0x616000002d80, reason: Session closed
[2015/04/28-10:41:07.175993] xio_connection.c:2303 [DEBUG] - got fin request send completion. session:0x61400001e640, connection:0x616000002d80
[2015/04/28-10:41:07.176022] xio_connection.c:2462 [DEBUG] - fin request received. session:0x61400000d840, connection:0x61600002e880
[2015/04/28-10:41:07.176036] xio_connection.c:1620 [DEBUG] - send fin response. session:0x61400000d840, connection:0x61600002e880
[2015/04/28-10:41:07.176077] xio_connection.c:2496 [DEBUG] - fin ack send completion received. session:0x61400000d840, connection:0x61600002e880
[2015/04/28-10:41:07.176087] xio_connection.c:2519 [DEBUG] - connection 0x61600002e880 state change: current_state:ONLINE, next_state:CLOSE_WAIT
[2015/04/28-10:41:07.176091] xio_connection.c:1578 [DEBUG] - send fin request. session:0x61400000d840, connection:0x61600002e880
[XIO_SERVER_PORTAL] On Session: connection closed. session:0x61400000d840, connection:0x61600002e880, reason: Session disconnected
[2015/04/28-10:41:07.176106] xio_connection.c:2540 [DEBUG] - connection 0x61600002e880 state change: current_state:CLOSE_WAIT, next_state:LAST_ACK
[2015/04/28-10:41:07.176111] xio_connection.c:2303 [DEBUG] - got fin request send completion. session:0x61400000d840, connection:0x61600002e880
[2015/04/28-10:41:07.176112] xio_connection.c:2390 [DEBUG] - got fin ack. session:0x61400001e640, connection:0x616000002d80
[2015/04/28-10:41:07.176138] xio_connection.c:2431 [DEBUG] - connection 0x616000002d80 state change: current_state:FIN_WAIT_1, next_state:FIN_WAIT_2
[2015/04/28-10:41:07.214664] xio_connection.c:2462 [DEBUG] - fin request received. session:0x61400001e640, connection:0x616000002d80
[2015/04/28-10:41:07.214696] xio_connection.c:1620 [DEBUG] - send fin response. session:0x61400001e640, connection:0x616000002d80
[2015/04/28-10:41:07.214730] xio_connection.c:2496 [DEBUG] - fin ack send completion received. session:0x61400001e640, connection:0x616000002d80
[2015/04/28-10:41:07.214757] xio_connection.c:2519 [DEBUG] - connection 0x616000002d80 state change: current_state:FIN_WAIT_2, next_state:TIME_WAIT
[2015/04/28-10:41:07.214748] xio_connection.c:2390 [DEBUG] - got fin ack. session:0x61400000d840, connection:0x61600002e880
[2015/04/28-10:41:07.214784] xio_connection.c:2355 [DEBUG] - connection 0x61600002e880 state change: current_state:LAST_ACK, next_state:CLOSED
[XIO_SERVER_PORTAL] On Session: connection teardown. session:0x61400000d840, connection:0x61600002e880, reason: Session disconnected
[2015/04/28-10:41:07.214815] xio_connection.c:2121 [DEBUG] - xio_connection_destroy. session:0x61400000d840, connection:0x61600002e880 nexus:0x61400000da40 nr:1, state:CLOSED
[2015/04/28-10:41:07.214823] xio_connection.c:2046 [DEBUG] - xio_connection_post_destroy. session:0x61400000d840, connection:0x61600002e880 conn:0x61400000da40 nr:1
[2015/04/28-10:41:07.214830] xio_nexus.c:2240 [TRACE] - nexus: [putref] ptr:0x61400000da40, refcnt:1
[2015/04/28-10:41:07.214837] xio_session_server.c:648 [DEBUG] - session: [notification] - connection closed. session:0x61400000d840, nexus:0x61400000da40
[2015/04/28-10:41:07.214844] xio_session.c:972 [TRACE] - session:0x61400000d840 - nexus:0x61400000da40 close complete
[2015/04/28-10:41:07.214852] xio_nexus.c:2212 [TRACE] - xio_nexus_deleyed close. nexus:0x61400000da40, state:4
[XIO_SERVER_PORTAL] On Session: session teardown. session:0x61400000d840, connection:(nil), reason: Session disconnected
[2015/04/28-10:41:07.214872] xio_session.c:1519 [TRACE] - session destroy:0x61400000d840
[2015/04/28-10:41:07.217059] xio_connection.c:2319 [DEBUG] - connection 0x616000002d80 state change: current_state:TIME_WAIT, next_state:CLOSED
[XIO_CLIENT_PORTAL] On Session: connection teardown. session:0x61400001e640, connection:0x616000002d80, reason: Session closed
[2015/04/28-10:41:07.217102] xio_connection.c:2121 [DEBUG] - xio_connection_destroy. session:0x61400001e640, connection:0x616000002d80 nexus:0x61400001e440 nr:1, state:CLOSED
[2015/04/28-10:41:07.217111] xio_connection.c:2046 [DEBUG] - xio_connection_post_destroy. session:0x61400001e640, connection:0x616000002d80 conn:0x61400001e440 nr:1
[2015/04/28-10:41:07.217119] xio_nexus.c:2240 [TRACE] - nexus: [putref] ptr:0x61400001e440, refcnt:1
[2015/04/28-10:41:07.217126] xio_session_client.c:805 [DEBUG] - session: [notification] - nexus closed. session:0x61400001e640, nexus:0x61400001e440
[2015/04/28-10:41:07.217133] xio_session.c:972 [TRACE] - session:0x61400001e640 - nexus:0x61400001e440 close complete
[2015/04/28-10:41:07.217142] xio_nexus.c:2212 [TRACE] - xio_nexus_deleyed close. nexus:0x61400001e440, state:4
[XIO_CLIENT_PORTAL] On Session: session teardown. session:0x61400001e640, connection:(nil), reason: Session closed
[2015/04/28-10:41:07.217162] xio_session.c:1519 [TRACE] - session destroy:0x61400001e640
[XIO_CLIENT_PORTAL] Destroy context: 0x626000002310
[2015/04/28-10:41:07.217486] xio_nexus.c:1246 [TRACE] - xio_on_server_event
[2015/04/28-10:41:07.217502] xio_nexus.c:1248 [TRACE] - server: [close] server:0x610000017340
[2015/04/28-10:41:07.217508] xio_nexus.c:1232 [TRACE] - xio_on_server_close. nexus:0x61400000da40, server:0x610000017340
[2015/04/28-10:41:07.217516] xio_nexus.c:1246 [TRACE] - xio_on_server_event
[2015/04/28-10:41:07.217522] xio_nexus.c:1248 [TRACE] - server: [close] server:0x610000017340
[2015/04/28-10:41:07.217529] xio_nexus.c:1232 [TRACE] - xio_on_server_close. nexus:0x61400000de40, server:0x610000017340
[2015/04/28-10:41:07.217536] xio_server.c:379 [DEBUG] - xio_server_destroy - server:0x610000017340
[2015/04/28-10:41:07.217542] xio_nexus.c:2240 [TRACE] - nexus: [putref] ptr:0x61400000de40, refcnt:1
[2015/04/28-10:41:07.217548] xio_nexus.c:2212 [TRACE] - xio_nexus_deleyed close. nexus:0x61400000de40, state:2
[2015/04/28-10:41:07.217555] xio_nexus.c:1182 [TRACE] - physical nexus close. nexus:0x61400000de40 rdma_hndl:0x62900005a200
[2015/04/28-10:41:07.217562] xio_nexus.c:1159 [TRACE] - physical nexus close. nexus:0x61400000de40 rdma_hndl:0x62900005a200
[2015/04/28-10:41:07.217568] xio_nexus.c:1166 [TRACE] - nexus state changed to closed
[2015/04/28-10:41:07.217575] xio_tcp_management.c:302 [TRACE] - xio_tcp_close: [close] handle:0x62900005a200, fd:10
[2015/04/28-10:41:07.217582] xio_tcp_management.c:226 [TRACE] - on_sock_disconnected. tcp_hndl:0x62900005a200, state:4
[2015/04/28-10:41:07.217589] xio_tcp_management.c:229 [TRACE] - call to close. tcp_hndl:0x62900005a200
[2015/04/28-10:41:07.217619] xio_tcp_management.c:156 [TRACE] - on_sock_close tcp_hndl:0x62900005a200, state:6

[2015/04/28-10:41:07.217628] xio_nexus.c:1742 [DEBUG] - nexus: [notification] - transport closed. nexus:0x61400000de40, transport:0x62900005a200
[2015/04/28-10:41:07.217635] xio_nexus.c:1796 [DEBUG] - nexus:0x61400000de40 - close complete
[2015/04/28-10:41:07.217644] xio_tcp_management.c:272 [TRACE] - tcp transport: [post close] handle:0x62900005a200
[2015/04/28-10:41:07.217654] xio_nexus.c:1216 [TRACE] - xio_on_context_event
[2015/04/28-10:41:07.217660] xio_nexus.c:1218 [TRACE] - context: [close] ctx:0x61500002ee80
[2015/04/28-10:41:07.217667] xio_nexus.c:1196 [TRACE] - xio_on_context_close. nexus:0x61400000da40, ctx:0x61500002ee80
[2015/04/28-10:41:07.217674] xio_tcp_management.c:461 [TRACE] - tcp transport context_shutdown handle:0x629000069200
[2015/04/28-10:41:07.217681] xio_tcp_management.c:226 [TRACE] - on_sock_disconnected. tcp_hndl:0x629000069200, state:4
[2015/04/28-10:41:07.217687] xio_tcp_management.c:229 [TRACE] - call to close. tcp_hndl:0x629000069200
[2015/04/28-10:41:07.217725] xio_tcp_management.c:141 [TRACE] - rx_list not empty!
[2015/04/28-10:41:07.217741] xio_nexus.c:1742 [DEBUG] - nexus: [notification] - transport closed. nexus:0x61400000da40, transport:0x629000069200
[2015/04/28-10:41:07.217748] xio_nexus.c:1796 [DEBUG] - nexus:0x61400000da40 - close complete
[2015/04/28-10:41:07.217756] xio_tcp_management.c:272 [TRACE] - tcp transport: [post close] handle:0x629000069200
[2015/04/28-10:41:07.218298] xio_connection.c:1723 [DEBUG] - xio_disconnect. session:0x61400000d840 connection:0x61600002e880 state:CLOSED
[ OK ] TestNetPortalFixture/0.SendSyncRequest (48 ms)

...

[2015/04/28-10:41:07.278391] xio_idr.c:172 [ERROR] - user object leaked: 0x61500000d280, type:struct xio_context

[Eyal Salomon (esalomon)]

Hi Christian,

Just quick question before diving in
Di you call xio_context_destroy before exit the process?

Eyal

נשלח מ-Type Mail

ב-28 באפר׳ 2015, 21:05, ב-Christian Tinnefeld <email address hidden>, 21:05 כתב:
>Public bug reported:
>
>Dear Accelio-Team,
>
>Sporadically xio complains about leaking user object of type struct
>xio_context, although the object has not been created in the user
>space.
>There are two places in my code where I call "xio_context_create" both
>are succeeded by a print out (..."Context pointer: %p"...) of the
>address. Please note that at the end of the attached log the address is
>printed of the supposedly leaking xio object ( 0x61500000d280 ), and
>that this address can also be found associated with the client session
>(" [2015/04/28-10:41:07.171155] xio_session_client.c:1019 [DEBUG] -
>xio_connect: session:0x61400001e640, connection:0x616000002d80,
>ctx:0x61500000d280, nexus:0x61400001e440 "), however it differs from
>the
>context object created in user space (" [XIO_CLIENT_PORTAL] Context
>pointer: 0x626000002310 ).
>
>My setup: Ubuntu 14.04, Accelio for_next branch, commit a5ab248,
>executed via TCP stack on localhost
>
>[ RUN ] TestNetPortalFixture/0.SendSyncRequest
>[2015/04/28-10:41:07.170675] xio_netlink.c:156 [DEBUG] -
>statistics monitoring disabled. not privileged user
>[XIO_SERVER_PORTAL] Context pointer: 0x61f00000bb48
>[2015/04/28-10:41:07.170703] xio_server.c:322 [TRACE] -
>bind to tcp://127.0.0.1:10010
>[2015/04/28-10:41:07.170730] xio_mempool.c:491 [DEBUG] -
>mempool: using huge pages allocator
>[2015/04/28-10:41:07.170754] xio_tcp_management.c:882 [TRACE] -
>xio_tcp_open: [new] handle:0x62900005a200
>[2015/04/28-10:41:07.170759] xio_nexus.c:2004 [TRACE] -
>nexus: [new] nexus:0x61400000de40, transport_hndl:0x62900005a200
>[2015/04/28-10:41:07.170791] xio_tcp_management.c:1275 [DEBUG] -
>listen on [tcp://127.0.0.1:10010] src_port:10010
>[XIO_SERVER_PORTAL] Open: tcp://127.0.0.1:10010
>[2015/04/28-10:41:07.170995] xio_netlink.c:156 [DEBUG] -
>statistics monitoring disabled. not privileged user
>[XIO_CLIENT_PORTAL] Context pointer: 0x626000002310
>[2015/04/28-10:41:07.171040] xio_mempool.c:491 [DEBUG] -
>mempool: using huge pages allocator
>[2015/04/28-10:41:07.171057] xio_tcp_management.c:882 [TRACE] -
>xio_tcp_open: [new] handle:0x629000073200
>[2015/04/28-10:41:07.171061] xio_nexus.c:2004 [TRACE] -
>nexus: [new] nexus:0x61400001e440, transport_hndl:0x629000073200
>[2015/04/28-10:41:07.171071] xio_nexus.c:2094 [TRACE] -
>xio_nexus_connect: nexus:0x61400001e440, rdma_hndl:0x629000073200,
>portal:tcp://127.0.0.1:10010
>[2015/04/28-10:41:07.171155] xio_session_client.c:1019 [DEBUG] -
>xio_connect: session:0x61400001e640, connection:0x616000002d80,
>ctx:0x61500000d280, nexus:0x61400001e440
>[2015/04/28-10:41:07.171533] xio_nexus.c:1731 [DEBUG] -
>nexus: [notification] - transport established. nexus:0x61400001e440,
>transport:0x629000073200
>[2015/04/28-10:41:07.171576] xio_tcp_management.c:882 [TRACE] -
>xio_tcp_open: [new] handle:0x629000069200
>[2015/04/28-10:41...