Failed to free iomgr objects before shutdown

[yihao yang]

Hi,

I'm using grpc stream to implement a Heartbeat session. When I ran one of the UT, I found the following logs. It said a failure to free an iomgr object. 

I want to know what does this mean and how can I investigate this?

Thanks,

Yihao

I0615 17:13:26.375270595   17953 completion_queue.c:333]     grpc_completion_queue_next(cc=0x7ffff0009a20, deadline=gpr_timespec { tv_sec: 9223372036854775807, tv_nsec: 0, clock_type: 1 }, reserved=(nil))

I0615 17:13:26.375282132   17953 completion_queue.c:394]     RETURN_EVENT[0x7ffff0009a20]: QUEUE_SHUTDOWN

I0615 17:13:26.375291770   17953 server.c:1277]              grpc_server_destroy(server=0x7ffff0009bf0)

I0615 17:13:26.385715087   17953 metadata_array.c:47]        grpc_metadata_array_destroy(array=0x7ffff0009ee0)

I0615 17:13:26.385730887   17953 metadata_array.c:47]        grpc_metadata_array_destroy(array=0x7ffff0009f60)

I0615 17:13:26.385739244   17953 metadata_array.c:47]        grpc_metadata_array_destroy(array=0x7ffff000a010)

I0615 17:13:26.385746288   17953 metadata_array.c:47]        grpc_metadata_array_destroy(array=0x7ffff000a190)

I0615 17:13:26.385755448   17953 metadata_array.c:47]        grpc_metadata_array_destroy(array=0x7ffff000a440)

I0615 17:13:26.385762962   17953 metadata_array.c:47]        grpc_metadata_array_destroy(array=0x7ffff000a380)

I0615 17:13:26.385769737   17953 metadata_array.c:47]        grpc_metadata_array_destroy(array=0x7ffff000a670)

I0615 17:13:26.385776443   17953 metadata_array.c:47]        grpc_metadata_array_destroy(array=0x7ffff000b710)

I0615 17:13:26.385784368   17953 completion_queue.c:561]     grpc_completion_queue_destroy(cc=0x7ffff0009a20)

I0615 17:13:26.385791429   17953 completion_queue.c:541]     grpc_completion_queue_shutdown(cc=0x7ffff0009a20)

I0615 17:13:26.385798643   17953 init.c:198]                 grpc_shutdown(void)

I0615 17:13:26.385806205   17953 init.c:198]                 grpc_shutdown(void)

I0615 17:13:26.385912 17953 gdict.cpp:291] Dictionary un-initialize start

W0615 17:13:26.385924 17953 heartbeat_client.cpp:235] CLIENT: AsyncStopSession failed, probably was issued already.Session:0xb1ab88 State:CLIENT_SESSION_EXPIRED

I0615 17:13:26.409771739   17988 completion_queue.c:394]     RETURN_EVENT[0xb56b60]: QUEUE_TIMEOUT

I0615 17:13:26.409795 17988 completion_queue_manager.cpp:103] Client CompletionQueue (0xb4e050) quit.

I0615 17:13:26.410217158   17953 completion_queue.c:541]     grpc_completion_queue_shutdown(cc=0xb56b60)

[Thread 0x7fffdb424700 (LWP 17988) exited]

I0615 17:13:26.410258122   17953 completion_queue.c:561]     grpc_completion_queue_destroy(cc=0xb56b60)

I0615 17:13:26.410267574   17953 completion_queue.c:541]     grpc_completion_queue_shutdown(cc=0xb56b60)

I0615 17:13:26.410274922   17953 init.c:198]                 grpc_shutdown(void)

I0615 17:13:26.410284 17953 completion_queue_manager.cpp:69] CQManager stopped.

I0615 17:13:26.410295318   17953 call.c:704]                 grpc_call_destroy(c=0xb52db0)

I0615 17:13:26.410303020   17953 call.c:735]                 grpc_call_cancel(call=0xb52db0, reserved=(nil))

I0615 17:13:26.410310459   17953 call.c:750]                 grpc_call_cancel_with_status(c=0xb52db0, status=1, description=Cancelled, reserved=(nil))

I0615 17:13:26.410347656   17953 client_channel.c:109]       OP[client-channel:0xb533b8]: CANCEL:{"created":"@1497572006.410318232","description":"Cancelled","file":"src/core/lib/surface/call.c","file_line":830,"grpc_message":"Cancelled","grpc_status":1}

I0615 17:13:26.410364135   17953 http_client_filter.c:171]   OP[http-client:0xb536f8]: CANCEL:{"created":"@1497572006.410318232","description":"Cancelled","file":"src/core/lib/surface/call.c","file_line":830,"grpc_message":"Cancelled","grpc_status":1}

I0615 17:13:26.410378504   17953 connected_channel.c:70]     OP[connected:0xb53710]: CANCEL:{"created":"@1497572006.410318232","description":"Cancelled","file":"src/core/lib/surface/call.c","file_line":830,"grpc_message":"Cancelled","grpc_status":1}

W0615 17:13:26.410403 17953 completion_queue_manager.cpp:26] 0xb4d920 ~CQManager

I0615 17:13:26.410413878   17953 channel.c:340]              grpc_channel_destroy(channel=0xb51ff0)

D0615 17:13:26.410428218   17953 connectivity_state.c:156]   SET: 0xb52138 client_channel: CONNECTING --> SHUTDOWN [disconnect] error=0xb56cb0 {"created":"@1497572006.410421973","description":"Channel Destroyed","file":"src/core/lib/surface/channel.c","file_line":342}

D0615 17:13:26.410445861   17953 connectivity_state.c:156]   SET: 0x7fffd0000c08 (null): CONNECTING --> SHUTDOWN [shutdown] error=0xb4d240 {"created":"@1497572006.410440651","description":"Channel shutdown","file":"src/core/ext/lb_policy/pick_first/pick_first.c","file_line":108}

D0615 17:13:26.410455711   17953 connectivity_state.c:183]   NOTIFY: 0x7fffc4001398

D0615 17:13:26.410462920   17953 connectivity_state.c:106]   CONWATCH: 0x7fffd0001048 subchannel: unsubscribe notify=0x7fffc4001b18

D0615 17:13:26.410487835   17953 connectivity_state.c:156]   SET: 0xb52138 client_channel: SHUTDOWN --> SHUTDOWN [resolver_gone] error=0xb57f50 {"created":"@1497572006.410472631","description":"Got config after disconnection","file":"src/core/ext/client_config/client_channel.c","file_line":250,"referenced_errors":[{"created":"@1497572006.410438479","description":"Resolver Shutdown","file":"src/core/ext/resolver/dns/native/dns_resolver.c","file_line":115}{"created":"@1497572006.410470581","description":"No load balancing policy","file":"src/core/ext/client_config/client_channel.c","file_line":188}]}

I0615 17:13:26.410504575   17953 init.c:198]                 grpc_shutdown(void)

D0615 17:13:26.410539717   17953 tcp_client_posix.c:104]     CLIENT_CONNECT: ipv4:127.0.0.1:19998: on_alarm: error={"created":"@1497572006.410527571","description":"Shutting down timer system","file":"src/core/lib/iomgr/timer.c","file_line":383}

D0615 17:13:26.410556237   17953 tcp_client_posix.c:104]     CLIENT_CONNECT: ipv6:[::1]:19998: on_alarm: error={"created":"@1497572006.410527571","description":"Shutting down timer system","file":"src/core/lib/iomgr/timer.c","file_line":383}

D0615 17:13:26.410569490   17953 tcp_client_posix.c:135]     CLIENT_CONNECT: ipv4:127.0.0.1:19998: on_writable: error={"created":"@1497572006.410552139","description":"FD shutdown","file":"src/core/lib/iomgr/ev_epoll_linux.c","file_line":948}

D0615 17:13:26.410590698   17953 tcp_client_posix.c:135]     CLIENT_CONNECT: ipv6:[::1]:19998: on_writable: error={"created":"@1497572006.410565136","description":"FD shutdown","file":"src/core/lib/iomgr/ev_epoll_linux.c","file_line":948}

D0615 17:13:27.411265239   17953 iomgr.c:101]                Waiting for 1 iomgr objects to be destroyed

D0615 17:13:28.411933344   17953 iomgr.c:101]                Waiting for 1 iomgr objects to be destroyed

D0615 17:13:29.412610900   17953 iomgr.c:101]                Waiting for 1 iomgr objects to be destroyed

D0615 17:13:30.413286453   17953 iomgr.c:101]                Waiting for 1 iomgr objects to be destroyed

D0615 17:13:31.413954083   17953 iomgr.c:101]                Waiting for 1 iomgr objects to be destroyed

D0615 17:13:32.414624888   17953 iomgr.c:101]                Waiting for 1 iomgr objects to be destroyed

D0615 17:13:33.415303038   17953 iomgr.c:101]                Waiting for 1 iomgr objects to be destroyed

D0615 17:13:34.415970005   17953 iomgr.c:101]                Waiting for 1 iomgr objects to be destroyed

D0615 17:13:35.416638599   17953 iomgr.c:101]                Waiting for 1 iomgr objects to be destroyed

D0615 17:13:36.417305375   17953 iomgr.c:120]                Failed to free 1 iomgr objects before shutdown deadline: memory leaks are likely

D0615 17:13:36.417318257   17953 iomgr.c:82]                 LEAKED OBJECT: workqueue:0x7fffc4001970 fd=10 0x7ffff000b1e0