Skip to content

php7_linux_dbg_native MemoryLeakTest.php failure due to memory leak detection #28390

@apolcyn

Description

@apolcyn

Looks like this has been happening recently on master branch. Log snippet example:

++ which valgrind
++ which php
+ /usr/bin/valgrind --error-exitcode=10 --leak-check=yes /usr/local/bin/php -d extension_dir=/var/local/git/grpc/src/php/bin/../ext/grpc/modules -d extension=grpc.so -d max_execution_time=300 ../tests/MemoryLeakTest/MemoryLeakTest.php
==11972== Memcheck, a memory error detector
==11972== Copyright (C) 2002-2015, and GNU GPL'd, by Julian Seward et al.
==11972== Using Valgrind-3.12.0.SVN and LibVEX; rerun with -h for copyright info
==11972== Command: /usr/local/bin/php -d extension_dir=/var/local/git/grpc/src/php/bin/../ext/grpc/modules -d extension=grpc.so -d max_execution_time=300 ../tests/MemoryLeakTest/MemoryLeakTest.php
==11972==

Warning: assert(): assert($state == true) failed in /var/local/git/grpc/src/php/tests/MemoryLeakTest/MemoryLeakTest.php on line 73
==11972==
==11972== HEAP SUMMARY:
==11972==     in use at exit: 162,454 bytes in 200 blocks
==11972==   total heap usage: 19,072 allocs, 18,872 frees, 2,806,532 bytes allocated
==11972==
==11972== 72 bytes in 1 blocks are possibly lost in loss record 93 of 132
==11972==    at 0x4C2DBC5: calloc (vg_replace_malloc.c:711)
==11972==    by 0xAE40EA2: gpr_zalloc (alloc.cc:44)
==11972==    by 0xAAB5C8B: g_poller_init_locked() (backup_poller.cc:144)
==11972==    by 0xAAB5DB1: grpc_client_channel_start_backup_polling(grpc_pollset_set*) (backup_poller.cc:164)
==11972==    by 0xAAB8D7A: grpc_core::ClientChannel::ClientChannel(grpc_channel_element_args*, grpc_error**) (client_channel.cc:1047)
==11972==    by 0xAAB88F6: grpc_core::ClientChannel::Init(grpc_channel_element*, grpc_channel_element_args*) (client_channel.cc:1002)
==11972==    by 0xAD1E474: grpc_channel_stack_init(int, void (*)(void*, grpc_error*), void*, grpc_channel_filter const**, unsigned long, grpc_channel_args const*, grpc_transport*, char const*, grpc_channel_stack*) (channel_stack.cc:135)
==11972==    by 0xAD1F431: grpc_channel_stack_builder_finish(grpc_channel_stack_builder*, unsigned long, int, void (*)(void*, grpc_error*), void*, void**) (channel_stack_builder.cc:288)
==11972==    by 0xADF6F65: grpc_channel_create_with_builder(grpc_channel_stack_builder*, grpc_channel_stack_type, grpc_error**) (channel.cc:75)
==11972==    by 0xADF79A2: grpc_channel_create(char const*, grpc_channel_args const*, grpc_channel_stack_type, grpc_transport*, grpc_error**) (channel.cc:275)
==11972==    by 0xAC3CFF4: grpc_core::(anonymous namespace)::CreateChannel(char const*, grpc_channel_args const*, grpc_error**) (channel_create.cc:68)
==11972==    by 0xAC3D1B4: grpc_insecure_channel_create (channel_create.cc:108)
==11972==
==11972== 248 bytes in 1 blocks are possibly lost in loss record 104 of 132
==11972==    at 0x4C2DBC5: calloc (vg_replace_malloc.c:711)
==11972==    by 0xAE40EA2: gpr_zalloc (alloc.cc:44)
==11972==    by 0xAAB5E60: (anonymous namespace)::backup_poller* grpc_core::Zalloc<(anonymous namespace)::backup_poller>() (memory.h:52)
==11972==    by 0xAAB5C70: g_poller_init_locked() (backup_poller.cc:142)
==11972==    by 0xAAB5DB1: grpc_client_channel_start_backup_polling(grpc_pollset_set*) (backup_poller.cc:164)
==11972==    by 0xAAB8D7A: grpc_core::ClientChannel::ClientChannel(grpc_channel_element_args*, grpc_error**) (client_channel.cc:1047)
==11972==    by 0xAAB88F6: grpc_core::ClientChannel::Init(grpc_channel_element*, grpc_channel_element_args*) (client_channel.cc:1002)
==11972==    by 0xAD1E474: grpc_channel_stack_init(int, void (*)(void*, grpc_error*), void*, grpc_channel_filter const**, unsigned long, grpc_channel_args const*, grpc_transport*, char const*, grpc_channel_stack*) (channel_stack.cc:135)
==11972==    by 0xAD1F431: grpc_channel_stack_builder_finish(grpc_channel_stack_builder*, unsigned long, int, void (*)(void*, grpc_error*), void*, void**) (channel_stack_builder.cc:288)
==11972==    by 0xADF6F65: grpc_channel_create_with_builder(grpc_channel_stack_builder*, grpc_channel_stack_type, grpc_error**) (channel.cc:75)
==11972==    by 0xADF79A2: grpc_channel_create(char const*, grpc_channel_args const*, grpc_channel_stack_type, grpc_transport*, grpc_error**) (channel.cc:275)
==11972==    by 0xAC3CFF4: grpc_core::(anonymous namespace)::CreateChannel(char const*, grpc_channel_args const*, grpc_error**) (channel_create.cc:68)
==11972==
==11972== 320 bytes in 1 blocks are possibly lost in loss record 109 of 132
==11972==    at 0x4C2DBC5: calloc (vg_replace_malloc.c:711)
==11972==    by 0x4011E31: allocate_dtv (dl-tls.c:322)
==11972==    by 0x40127BD: _dl_allocate_tls (dl-tls.c:539)
==11972==    by 0x6EB6189: allocate_stack (allocatestack.c:584)
==11972==    by 0x6EB6189: pthread_create@@GLIBC_2.2.5 (pthread_create.c:663)
==11972==    by 0xAE4632D: grpc_core::(anonymous namespace)::ThreadInternalsPosix::ThreadInternalsPosix(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&) (thd_posix.cc:108)
==11972==    by 0xAE46501: grpc_core::Thread::Thread(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&) (thd_posix.cc:186)
==11972==    by 0xAD54D56: grpc_core::Executor::SetThreading(bool) (executor.cc:172)
==11972==    by 0xAD548F8: grpc_core::Executor::Init() (executor.cc:97)
==11972==    by 0xAD5590E: grpc_core::Executor::InitAll() (executor.cc:392)
==11972==    by 0xAD57ECC: grpc_iomgr_init() (iomgr.cc:62)
==11972==    by 0xAE02CDE: grpc_init (init.cc:113)
==11972==    by 0x9F39AC7: zm_activate_grpc (in /var/local/git/grpc/src/php/ext/grpc/modules/grpc.so)
==11972==
==11972== 320 bytes in 1 blocks are possibly lost in loss record 110 of 132
==11972==    at 0x4C2DBC5: calloc (vg_replace_malloc.c:711)
==11972==    by 0x4011E31: allocate_dtv (dl-tls.c:322)
==11972==    by 0x40127BD: _dl_allocate_tls (dl-tls.c:539)
==11972==    by 0x6EB6189: allocate_stack (allocatestack.c:584)
==11972==    by 0x6EB6189: pthread_create@@GLIBC_2.2.5 (pthread_create.c:663)
==11972==    by 0xAE4632D: grpc_core::(anonymous namespace)::ThreadInternalsPosix::ThreadInternalsPosix(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&) (thd_posix.cc:108)
==11972==    by 0xAE46501: grpc_core::Thread::Thread(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&) (thd_posix.cc:186)
==11972==    by 0xAD54D56: grpc_core::Executor::SetThreading(bool) (executor.cc:172)
==11972==    by 0xAD548F8: grpc_core::Executor::Init() (executor.cc:97)
==11972==    by 0xAD5591D: grpc_core::Executor::InitAll() (executor.cc:393)
==11972==    by 0xAD57ECC: grpc_iomgr_init() (iomgr.cc:62)
==11972==    by 0xAE02CDE: grpc_init (init.cc:113)
==11972==    by 0x9F39AC7: zm_activate_grpc (in /var/local/git/grpc/src/php/ext/grpc/modules/grpc.so)
==11972==
==11972== 320 bytes in 1 blocks are possibly lost in loss record 111 of 132
==11972==    at 0x4C2DBC5: calloc (vg_replace_malloc.c:711)
==11972==    by 0x4011E31: allocate_dtv (dl-tls.c:322)
==11972==    by 0x40127BD: _dl_allocate_tls (dl-tls.c:539)
==11972==    by 0x6EB6189: allocate_stack (allocatestack.c:584)
==11972==    by 0x6EB6189: pthread_create@@GLIBC_2.2.5 (pthread_create.c:663)
==11972==    by 0xAE4632D: grpc_core::(anonymous namespace)::ThreadInternalsPosix::ThreadInternalsPosix(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&) (thd_posix.cc:108)
==11972==    by 0xAE46501: grpc_core::Thread::Thread(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&) (thd_posix.cc:186)
==11972==    by 0xAD6F2F3: start_timer_thread_and_unlock() (timer_manager.cc:92)
==11972==    by 0xAD6F8C5: start_threads() (timer_manager.cc:293)
==11972==    by 0xAD6F941: grpc_timer_manager_init() (timer_manager.cc:311)
==11972==    by 0xAD57F28: grpc_iomgr_start() (iomgr.cc:71)
==11972==    by 0xAE02D3A: grpc_init (init.cc:121)
==11972==    by 0x9F39AC7: zm_activate_grpc (in /var/local/git/grpc/src/php/ext/grpc/modules/grpc.so)
==11972==
==11972== 320 bytes in 1 blocks are possibly lost in loss record 112 of 132
==11972==    at 0x4C2DBC5: calloc (vg_replace_malloc.c:711)
==11972==    by 0x4011E31: allocate_dtv (dl-tls.c:322)
==11972==    by 0x40127BD: _dl_allocate_tls (dl-tls.c:539)
==11972==    by 0x6EB6189: allocate_stack (allocatestack.c:584)
==11972==    by 0x6EB6189: pthread_create@@GLIBC_2.2.5 (pthread_create.c:663)
==11972==    by 0xAE4632D: grpc_core::(anonymous namespace)::ThreadInternalsPosix::ThreadInternalsPosix(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&) (thd_posix.cc:108)
==11972==    by 0xAE46501: grpc_core::Thread::Thread(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&) (thd_posix.cc:186)
==11972==    by 0xAD6F2F3: start_timer_thread_and_unlock() (timer_manager.cc:92)
==11972==    by 0xAD6F39C: run_some_timers() (timer_manager.cc:118)
==11972==    by 0xAD6F741: timer_main_loop() (timer_manager.cc:237)
==11972==    by 0xAD6F880: timer_thread(void*) (timer_manager.cc:284)
==11972==    by 0xAE46020: grpc_core::(anonymous namespace)::ThreadInternalsPosix::ThreadInternalsPosix(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&)::{lambda(void*)#1}::operator()(void*) const (thd_posix.cc:140)
==11972==    by 0xAE46051: grpc_core::(anonymous namespace)::ThreadInternalsPosix::ThreadInternalsPosix(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&)::{lambda(void*)#1}::_FUN(void*) (thd_posix.cc:145)
==11972==
==11972== 320 bytes in 1 blocks are possibly lost in loss record 113 of 132
==11972==    at 0x4C2DBC5: calloc (vg_replace_malloc.c:711)
==11972==    by 0x4011E31: allocate_dtv (dl-tls.c:322)
==11972==    by 0x40127BD: _dl_allocate_tls (dl-tls.c:539)
==11972==    by 0x6EB6189: allocate_stack (allocatestack.c:584)
==11972==    by 0x6EB6189: pthread_create@@GLIBC_2.2.5 (pthread_create.c:663)
==11972==    by 0xAE4632D: grpc_core::(anonymous namespace)::ThreadInternalsPosix::ThreadInternalsPosix(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&) (thd_posix.cc:108)
==11972==    by 0xAE46501: grpc_core::Thread::Thread(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&) (thd_posix.cc:186)
==11972==    by 0xAE03075: grpc_shutdown (init.cc:190)
==11972==    by 0xADF8908: destroy_channel(void*, grpc_error*) (channel.cc:489)
==11972==    by 0xAD53E52: exec_ctx_run(grpc_closure*) (exec_ctx.cc:49)
==11972==    by 0xAD5438F: grpc_core::ExecCtx::Flush() (exec_ctx.cc:164)
==11972==    by 0xAD6F44D: run_some_timers() (timer_manager.cc:134)
==11972==    by 0xAD6F741: timer_main_loop() (timer_manager.cc:237)
==11972==
==11972== 352 bytes in 2 blocks are possibly lost in loss record 114 of 132
==11972==    at 0x4C2E136: memalign (vg_replace_malloc.c:858)
==11972==    by 0x4011F57: allocate_and_init (dl-tls.c:603)
==11972==    by 0x4011F57: tls_get_addr_tail (dl-tls.c:791)
==11972==    by 0x4017137: __tls_get_addr (tls_get_addr.S:55)
==11972==    by 0xAD5514F: grpc_core::Executor::ThreadMain(void*) (executor.cc:224)
==11972==    by 0xAE46020: grpc_core::(anonymous namespace)::ThreadInternalsPosix::ThreadInternalsPosix(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&)::{lambda(void*)#1}::operator()(void*) const (thd_posix.cc:140)
==11972==    by 0xAE46051: grpc_core::(anonymous namespace)::ThreadInternalsPosix::ThreadInternalsPosix(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&)::{lambda(void*)#1}::_FUN(void*) (thd_posix.cc:145)
==11972==    by 0x6EB54A3: start_thread (pthread_create.c:456)
==11972==    by 0x6BF7D0E: clone (clone.S:97)
==11972==
==11972== 352 bytes in 2 blocks are possibly lost in loss record 115 of 132
==11972==    at 0x4C2E136: memalign (vg_replace_malloc.c:858)
==11972==    by 0x4011F57: allocate_and_init (dl-tls.c:603)
==11972==    by 0x4011F57: tls_get_addr_tail (dl-tls.c:791)
==11972==    by 0x4017137: __tls_get_addr (tls_get_addr.S:55)
==11972==    by 0xAAB5FF4: TLS wrapper function for grpc_core::ExecCtx::exec_ctx_ (in /var/local/git/grpc/libs/dbg/libgrpc.so.21.0.0)
==11972==    by 0xAAB5FFF: grpc_core::ExecCtx::Get() (exec_ctx.h:222)
==11972==    by 0xAD56058: grpc_core::ExecCtx::ExecCtx(unsigned long) (exec_ctx.h:251)
==11972==    by 0xAD6F87B: timer_thread(void*) (timer_manager.cc:283)
==11972==    by 0xAE46020: grpc_core::(anonymous namespace)::ThreadInternalsPosix::ThreadInternalsPosix(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&)::{lambda(void*)#1}::operator()(void*) const (thd_posix.cc:140)
==11972==    by 0xAE46051: grpc_core::(anonymous namespace)::ThreadInternalsPosix::ThreadInternalsPosix(char const*, void (*)(void*), void*, bool*, grpc_core::Thread::Options const&)::{lambda(void*)#1}::_FUN(void*) (thd_posix.cc:145)
==11972==    by 0x6EB54A3: start_thread (pthread_create.c:456)
==11972==    by 0x6BF7D0E: clone (clone.S:97)
==11972==
==11972== 1,312 bytes in 1 blocks are possibly lost in loss record 123 of 132
==11972==    at 0x4C2BBAF: malloc (vg_replace_malloc.c:299)
==11972==    by 0xAE40E61: gpr_malloc (alloc.cc:33)
==11972==    by 0xAD49D97: pollable_create(pollable_type, pollable**) (ev_epollex_linux.cc:566)
==11972==    by 0xAD4C12F: pollset_as_multipollable_locked(grpc_pollset*, pollable**) (ev_epollex_linux.cc:1242)
==11972==    by 0xAD4CDC1: pollset_set_add_pollset(grpc_pollset_set*, grpc_pollset*) (ev_epollex_linux.cc:1454)
==11972==    by 0xAD538DC: pollset_set_add_pollset(grpc_pollset_set*, grpc_pollset*) (ev_posix.cc:365)
==11972==    by 0xAD59C49: grpc_pollset_set_add_pollset(grpc_pollset_set*, grpc_pollset*) (pollset_set.cc:39)
==11972==    by 0xAAB5DF7: grpc_client_channel_start_backup_polling(grpc_pollset_set*) (backup_poller.cc:173)
==11972==    by 0xAAB8D7A: grpc_core::ClientChannel::ClientChannel(grpc_channel_element_args*, grpc_error**) (client_channel.cc:1047)
==11972==    by 0xAAB88F6: grpc_core::ClientChannel::Init(grpc_channel_element*, grpc_channel_element_args*) (client_channel.cc:1002)
==11972==    by 0xAD1E474: grpc_channel_stack_init(int, void (*)(void*, grpc_error*), void*, grpc_channel_filter const**, unsigned long, grpc_channel_args const*, grpc_transport*, char const*, grpc_channel_stack*) (channel_stack.cc:135)
==11972==    by 0xAD1F431: grpc_channel_stack_builder_finish(grpc_channel_stack_builder*, unsigned long, int, void (*)(void*, grpc_error*), void*, void**) (channel_stack_builder.cc:288)
==11972==
==11972== LEAK SUMMARY:
==11972==    definitely lost: 0 bytes in 0 blocks
==11972==    indirectly lost: 0 bytes in 0 blocks
==11972==      possibly lost: 3,936 bytes in 12 blocks
==11972==    still reachable: 158,518 bytes in 188 blocks
==11972==                       of which reachable via heuristic:
==11972==                         newarray           : 1,032 bytes in 1 blocks
==11972==         suppressed: 0 bytes in 0 blocks
==11972== Reachable blocks (those to which a pointer was found) are not shown.
==11972== To see them, rerun with: --leak-check=full --show-leak-kinds=all
==11972==
==11972== For counts of detected and suppressed errors, rerun with: -v
==11972== ERROR SUMMARY: 10 errors from 10 contexts (suppressed: 0 from 0)

2021-12-20 18:51:57,192 FAILED: src/php/bin/run_tests.sh [ret=10, pid=11950, time=5.8sec]
2021-12-20 18:51:57,192 FAILED: src/php/bin/run_tests.sh
2021-12-20 18:51:57,197 START: tools/run_tests/helper_scripts/post_tests_php.sh
2021-12-20 18:51:57,201 PASSED: tools/run_tests/helper_scripts/post_tests_php.sh [time=0.0sec, retries=0:0]
2021-12-20 18:51:57,201 FAILED: Some tests failed
  adding: reports/ (stored 0%)
  adding: run_tests/php7_linux_dbg_native/src/php/bin/run_tests.sh/sponge_log.xml (deflated 83%)
+ DOCKER_EXIT_CODE=2
++ mktemp
+ TEMP_REPORTS_ZIP=/tmpfs/tmp/tmp.Jd5ThLGZh8
+ docker cp run_tests_c6cfc3b8-5570-4ba6-87c0-11400e68062e:/var/local/git/grpc/reports.zip /tmpfs/tmp/tmp.Jd5ThLGZh8
+ '[' /tmpfs/src/github/grpc '!=' '' ']'
+ REPORTS_DEST_DIR=/tmpfs/src/github/grpc
+ unzip -o /tmpfs/tmp/tmp.Jd5ThLGZh8 -d /tmpfs/src/github/grpc
Archive:  /tmpfs/tmp/tmp.Jd5ThLGZh8
   creating: /tmpfs/src/github/grpc/reports/
  inflating: /tmpfs/src/github/grpc/run_tests/php7_linux_dbg_native/src/php/bin/run_tests.sh/sponge_log.xml
+ rm -f /tmpfs/tmp/tmp.Jd5ThLGZh8
+ docker rm -f run_tests_c6cfc3b8-5570-4ba6-87c0-11400e68062e
run_tests_c6cfc3b8-5570-4ba6-87c0-11400e68062e
+ exit 2
Traceback (most recent call last):
  File "tools/run_tests/run_tests.py", line 1612, in <module>
    env=env)
  File "/usr/lib/python3.5/subprocess.py", line 581, in check_call
    raise CalledProcessError(retcode, cmd)
subprocess.CalledProcessError: Command 'tools/run_tests/dockerize/build_docker_and_run_tests.sh' returned non-zero exit status 2

https://source.cloud.google.com/results/invocations/700e1759-8bd5-4d60-a6fc-aa803132d3c0/targets/github%2Fgrpc%2Ftoplevel_run_tests_invocations%2Frun_tests_php7_linux_dbg_native/tests

Metadata

Metadata

Type

No type

Projects

No projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions