Skip to content

Instantly share code, notes, and snippets.

@lidizheng

lidizheng/gist:820bcfa1e0d2b052e4e8280e418acad3

Last active September 6, 2019 01:13
Show Gist options
  • Save lidizheng/820bcfa1e0d2b052e4e8280e418acad3 to your computer and use it in GitHub Desktop.
Save lidizheng/820bcfa1e0d2b052e4e8280e418acad3 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
gistfile1.txt
lidiz@ddev:google3$ GRPC_VERBOSITY=debug GRPC_TRACE=metadata blaze-out/k8-py3-dbg/bin/third_party/py/grpc/tests_aio/unit/channel_test_opensource --logtostderr
Running tests under Python 3.6.7: embedded.
[ RUN ] TestChannel.test_async_context
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], setUp
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], start new process
D0905 18:12:55.626506482 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626540271 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626547992 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626555874 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626562042 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626569486 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626575870 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626581655 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626587091 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626592738 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626598611 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626604009 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626609131 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626614941 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626620132 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.626625515 208881 metadata.cc:241] shard->count = 0
D0905 18:12:55.627171584 208881 ev_posix.cc:174] Using polling engine: epollex
D0905 18:12:55.627511350 208881 dns_resolver_ares.cc:485] Using ares dns resolver
In process [208881] thread [<_MainThread(MainThread, started 140346284608192)>], server started
D0905 18:12:55.683603629 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683657717 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683676047 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683691137 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683707458 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683722016 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683737842 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683752570 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683770165 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683785278 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683805175 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683825147 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683849334 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683863834 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683877884 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.683900967 208877 metadata.cc:241] shard->count = 0
D0905 18:12:55.684374366 208877 dns_resolver.cc:294] Using native dns resolver
D0905 18:12:55.693664575 208877 metadata.cc:162] mdelem ALLOC_MD_NOREF_KEY:0x7fa4bfc72a30:1: ':path' = '/grpc.testing.TestService/UnaryCall'
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], _store_c_metadata None
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], RECV ini init
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], RECV status init
D0905 18:12:55.694125247 208877 dns_resolver.cc:242] Start resolving.
D0905 18:12:55.699975542 208877 metadata.cc:162] mdelem INTERNED_MD_NOREF_KEY:0x7fa4bfc72550:1: ':authority' = '[::1]:43983'
D0905 18:12:55.700016651 208877 metadata.cc:481] shard->count++, i=13, 1, key=:authority, value=[::1]:43983
D0905 18:12:55.700067881 208877 metadata.cc:162] mdelem INTERNED_MD_NOREF_KEY:0x7fa4bfc727c0:1: 'user-agent' = 'grpc-c/8.0.0 (linux; chttp2; ganges)'
D0905 18:12:55.700090889 208877 metadata.cc:481] shard->count++, i=1, 1, key=user-agent, value=grpc-c/8.0.0 (linux; chttp2; ganges)
I0905 18:12:55.700160988 208877 subchannel.cc:1086] New connected subchannel at 0x7fa4bf400500 for subchannel 0x7fa4bf928da0
D0905 18:12:55.700522175 208877 client_authority_filter.cc:63] mdelem REF:0x7fa4bfc72550:1->2: ':authority' = '[::1]:43983' process [27419]
D0905 18:12:55.700565945 208877 metadata.cc:162] mdelem ALLOC_MD_NOREF_KEY_VAL:0x7fa4bfc726f0:1: ':path' = '/grpc.testing.TestService/UnaryCall?'
D0905 18:12:55.700593388 208877 metadata_batch.cc:310] mdelem UNREF:0x7fa4bfc72a30:1->0: ':path' = '/grpc.testing.TestService/UnaryCall' process [27419]
D0905 18:12:55.700630815 208877 http_client_filter.cc:453] mdelem REF:0x7fa4bfc727c0:1->2: 'user-agent' = 'grpc-c/8.0.0 (linux; chttp2; ganges)' process [27419]
D0905 18:12:55.700686837 208877 hpack_encoder.cc:286] mdelem REF:0x7fa4bfc72550:2->3: ':authority' = '[::1]:43983' process [27419]
D0905 18:12:55.700782859 208877 hpack_encoder.cc:286] mdelem REF:0x7fa4bfc727c0:2->3: 'user-agent' = 'grpc-c/8.0.0 (linux; chttp2; ganges)' process [27419]
D0905 18:12:55.700995179 208885 metadata.cc:162] mdelem INTERNED_MD:0x7fa4bfc72890:1: ':authority' = '[::1]:43983'
D0905 18:12:55.701044216 208885 metadata.cc:481] shard->count++, i=10, 1, key=:authority, value=[::1]:43983
D0905 18:12:55.701082797 208885 hpack_table.cc:192] mdelem REF:0x7fa4bfc72890:1->2: ':authority' = '[::1]:43983' process [208877]
D0905 18:12:55.701120466 208885 metadata.cc:162] mdelem INTERNED_MD:0x7fa4bfc72b00:1: ':path' = '/grpc.testing.TestService/UnaryCall?'
D0905 18:12:55.701144929 208885 metadata.cc:481] shard->count++, i=9, 1, key=:path, value=/grpc.testing.TestService/UnaryCall?
D0905 18:12:55.701170251 208885 hpack_table.cc:192] mdelem REF:0x7fa4bfc72b00:1->2: ':path' = '/grpc.testing.TestService/UnaryCall?' process [208877]
D0905 18:12:55.701209527 208885 metadata.cc:162] mdelem INTERNED_MD:0x7fa4bfc722e0:1: 'user-agent' = 'grpc-c/8.0.0 (linux; chttp2; ganges)'
D0905 18:12:55.701258058 208885 metadata.cc:481] shard->count++, i=14, 1, key=user-agent, value=grpc-c/8.0.0 (linux; chttp2; ganges)
D0905 18:12:55.701284720 208885 hpack_table.cc:192] mdelem REF:0x7fa4bfc722e0:1->2: 'user-agent' = 'grpc-c/8.0.0 (linux; chttp2; ganges)' process [208877]
D0905 18:12:55.701353273 208885 metadata.cc:162] mdelem ALLOC_MD_NOREF_KEY:0x7fa4bfc73250:1: ':path' = '/grpc.testing.TestService/UnaryCall'
D0905 18:12:55.701384140 208885 metadata_batch.cc:310] mdelem UNREF:0x7fa4bfc72b00:2->1: ':path' = '/grpc.testing.TestService/UnaryCall?' process [208877]
D0905 18:12:55.701413439 208885 metadata_batch.cc:280] mdelem UNREF:0x7fa4bfc73250:1->0: ':path' = '/grpc.testing.TestService/UnaryCall' process [208877]
D0905 18:12:55.701446692 208885 metadata_batch.cc:280] mdelem UNREF:0x7fa4bfc72890:2->1: ':authority' = '[::1]:43983' process [208877]
In process [208881] thread [<Thread(ThreadPoolExecutor-0_0, started daemon 140346221999872)>], _store_c_metadata None
In process [208881] thread [<Thread(ThreadPoolExecutor-0_0, started daemon 140346221999872)>], _store_c_metadata None
D0905 18:12:55.704024738 208890 metadata.cc:162] mdelem ALLOC_MD_NOREF_KEY:0x7fa4bfc73320:1: 'grpc-message' = ''
D0905 18:12:55.704220471 208890 metadata_batch.cc:84] mdelem UNREF:0x7fa4bfc73320:1->0: 'grpc-message' = '' process [208877]
In process [208881] thread [<Thread(Thread-1, started daemon 140346230392576)>], _release_c_metadata 0
In process [208881] thread [<Thread(Thread-1, started daemon 140346230392576)>], _release_c_metadata 0
D0905 18:12:55.704724187 208877 metadata.cc:162] mdelem INTERNED_MD:0x7fa4bfc72890:1: 'grpc-message' = ''
D0905 18:12:55.704758056 208877 metadata.cc:481] shard->count++, i=4, 1, key=grpc-message, value=
D0905 18:12:55.704778535 208877 hpack_table.cc:192] mdelem REF:0x7fa4bfc72890:1->2: 'grpc-message' = '' process [27419]
D0905 18:12:55.704778705 208885 metadata_batch.cc:84] mdelem UNREF:0x7fa4bfc722e0:2->1: 'user-agent' = 'grpc-c/8.0.0 (linux; chttp2; ganges)' process [208877]
D0905 18:12:55.704891747 208877 metadata_batch.cc:280] mdelem UNREF:0x7fa4bfc72890:2->1: 'grpc-message' = '' process [27419]
D0905 18:12:55.704916896 208877 metadata_batch.cc:84] mdelem UNREF:0x7fa4bfc72550:3->2: ':authority' = '[::1]:43983' process [27419]
D0905 18:12:55.704936025 208877 metadata_batch.cc:84] mdelem UNREF:0x7fa4bfc726f0:1->0: ':path' = '/grpc.testing.TestService/UnaryCall?' process [27419]
D0905 18:12:55.704962550 208877 metadata_batch.cc:84] mdelem UNREF:0x7fa4bfc727c0:3->2: 'user-agent' = 'grpc-c/8.0.0 (linux; chttp2; ganges)' process [27419]
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], _release_c_metadata 0
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], RECV ini destory
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], RECV status destroy
D0905 18:12:55.705700625 208877 client_authority_filter.cc:116] mdelem UNREF:0x7fa4bfc72550:2->1: ':authority' = '[::1]:43983' process [27419]
D0905 18:12:55.705733249 208877 http_client_filter.cc:587] mdelem UNREF:0x7fa4bfc727c0:2->1: 'user-agent' = 'grpc-c/8.0.0 (linux; chttp2; ganges)' process [27419]
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], tearDown
D0905 18:12:55.706395929 208885 hpack_table.cc:41] mdelem UNREF:0x7fa4bfc72890:1->0: ':authority' = '[::1]:43983' process [208877]
D0905 18:12:55.706462180 208885 hpack_table.cc:41] mdelem UNREF:0x7fa4bfc72b00:1->0: ':path' = '/grpc.testing.TestService/UnaryCall?' process [208877]
In process [208881] thread [<_MainThread(MainThread, started 140346284608192)>], SIGTERM received
D0905 18:12:55.706521705 208885 hpack_table.cc:41] mdelem UNREF:0x7fa4bfc722e0:1->0: 'user-agent' = 'grpc-c/8.0.0 (linux; chttp2; ganges)' process [208877]
[ OK ] TestChannel.test_async_context
[ RUN ] TestChannel.test_unary_unary
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], setUp
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], _aio_prefork
D0905 18:12:55.707735015 208881 metadata.cc:208] CleanupLinkedMetadata md=140345568865024 ref=0
D0905 18:12:55.707770799 208881 metadata.cc:317] shard->count -= 1, i=5 0
D0905 18:12:55.707790438 208881 metadata.cc:208] CleanupLinkedMetadata md=140345568864400 ref=0
D0905 18:12:55.707812841 208881 metadata.cc:317] shard->count -= 1, i=0 0
D0905 18:12:55.707835465 208881 metadata.cc:208] CleanupLinkedMetadata md=140345568862944 ref=0
D0905 18:12:55.707856735 208881 metadata.cc:317] shard->count -= 1, i=3 0
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], _aio_postfork_parent
In process [208891] thread [<_MainThread(MainThread, started 140346284608192)>], _aio_postfork_child
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], start new process
D0905 18:12:55.711975907 208877 metadata.cc:208] CleanupLinkedMetadata md=140345568864192 ref=1
D0905 18:12:55.712097153 208877 metadata.cc:261] SHARD metadata:0x7fa4bfc727c0 key=user-agent value=grpc-c/8.0.0 (linux; chttp2; ganges)
D0905 18:12:55.712131957 208877 metadata.cc:267] WARNING: 1 metadata elements were leaked process [208877] i=1
E0905 18:12:55.712149508 208877 metadata.cc:277] assertion failed: shard->count == 0
Fatal Python error: Aborted
Thread 0x00007fa4e7b55700 (most recent call first):
File "<embedded stdlib>/threading.py", line 295 in wait
File "<embedded stdlib>/queue.py", line 164 in get
File "<embedded stdlib>/concurrent/futures/thread.py", line 67 in _worker
File "<embedded stdlib>/threading.py", line 864 in run
File "<embedded stdlib>/threading.py", line 916 in _bootstrap_inner
File "<embedded stdlib>/threading.py", line 884 in _bootstrap
Current thread 0x00007fa4ea708ac0 (most recent call first):
File "<embedded stdlib>/multiprocessing/popen_fork.py", line 66 in _launch
File "<embedded stdlib>/multiprocessing/popen_fork.py", line 19 in __init__
File "<embedded stdlib>/multiprocessing/context.py", line 277 in _Popen
File "<embedded stdlib>/multiprocessing/context.py", line 223 in _Popen
File "<embedded stdlib>/multiprocessing/process.py", line 105 in start
File "/google/src/cloud/lidiz/github-sync-20190904165325/google3/blaze-out/k8-py3-dbg/bin/third_party/py/grpc/tests_aio/unit/channel_test_opensource.runfiles/google3/third_party/py/grpc/tests_aio/unit/sync_server.py", line 50 in start
File "/google/src/cloud/lidiz/github-sync-20190904165325/google3/blaze-out/k8-py3-dbg/bin/third_party/py/grpc/tests_aio/unit/channel_test_opensource.runfiles/google3/third_party/py/grpc/tests_aio/unit/test_base.py", line 46 in setUp
File "<embedded stdlib>/unittest/case.py", line 601 in run
File "<embedded stdlib>/unittest/case.py", line 653 in __call__
File "<embedded stdlib>/unittest/suite.py", line 122 in run
File "<embedded stdlib>/unittest/suite.py", line 84 in __call__
File "<embedded stdlib>/unittest/suite.py", line 122 in run
File "<embedded stdlib>/unittest/suite.py", line 84 in __call__
File "<embedded stdlib>/unittest/runner.py", line 176 in run
File "/google/src/cloud/lidiz/github-sync-20190904165325/google3/blaze-out/k8-py3-dbg/bin/third_party/py/grpc/tests_aio/unit/channel_test_opensource.runfiles/google3/third_party/py/absl/testing/_pretty_print_reporter.py", line 86 in run
File "<embedded stdlib>/unittest/main.py", line 256 in runTests
File "<embedded stdlib>/unittest/main.py", line 95 in __init__
File "/google/src/cloud/lidiz/github-sync-20190904165325/google3/blaze-out/k8-py3-dbg/bin/third_party/py/grpc/tests_aio/unit/channel_test_opensource.runfiles/google3/third_party/py/absl/testing/absltest.py", line 2338 in _run_and_get_tests_result
File "/google/src/cloud/lidiz/github-sync-20190904165325/google3/blaze-out/k8-py3-dbg/bin/third_party/py/grpc/tests_aio/unit/channel_test_opensource.runfiles/google3/testing/pybase/googletest.py", line 923 in RunTests
File "/google/src/cloud/lidiz/github-sync-20190904165325/google3/blaze-out/k8-py3-dbg/bin/third_party/py/grpc/tests_aio/unit/channel_test_opensource.runfiles/google3/third_party/py/absl/testing/absltest.py", line 2097 in main_function
File "/google/src/cloud/lidiz/github-sync-20190904165325/google3/blaze-out/k8-py3-dbg/bin/third_party/py/grpc/tests_aio/unit/channel_test_opensource.runfiles/google3/third_party/py/absl/app.py", line 385 in _run_main
File "/google/src/cloud/lidiz/github-sync-20190904165325/google3/blaze-out/k8-py3-dbg/bin/third_party/py/grpc/tests_aio/unit/channel_test_opensource.runfiles/google3/third_party/py/absl/app.py", line 456 in run
File "/google/src/cloud/lidiz/github-sync-20190904165325/google3/blaze-out/k8-py3-dbg/bin/third_party/py/grpc/tests_aio/unit/channel_test_opensource.runfiles/google3/third_party/py/absl/testing/absltest.py", line 2099 in _run_in_app
File "/google/src/cloud/lidiz/github-sync-20190904165325/google3/blaze-out/k8-py3-dbg/bin/third_party/py/grpc/tests_aio/unit/channel_test_opensource.runfiles/google3/testing/pybase/googletest.py", line 871 in main
File "/google/src/cloud/lidiz/github-sync-20190904165325/google3/blaze-out/k8-py3-dbg/bin/third_party/py/grpc/tests_aio/unit/channel_test_opensource.runfiles/google3/third_party/py/grpc/tests_aio/unit/channel_test.py", line 57 in <module>
File "<embedded module '_launcher'>", line 33 in _run_code_in_main
File "<embedded module '_launcher'>", line 149 in run_filename_as_main
D0905 18:12:55.813538784 208877 metadata.cc:162] mdelem ALLOC_MD_NOREF_KEY:0x7fa4bfc72b00:1: ':path' = '/grpc.testing.TestService/UnaryCall'
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], _store_c_metadata None
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], RECV ini init
In process [208877] thread [<_MainThread(MainThread, started 140346284608192)>], RECV status init
D0905 18:12:55.813976394 208877 dns_resolver.cc:242] Start resolving.
I0905 18:12:55.822091012 208877 subchannel.cc:1034] Connect failed: {"created":"@1567732375.821944883","description":"connect [Errno 111] Connect call failed ('::1', 56765, 0, 0)","file":"third_party/grpc/src/core/lib/iomgr/gevent_util.h","file_line":33,"grpc_status":14}
D0905 18:12:55.822156973 208877 dns_resolver.cc:223] In cooldown from last resolution (from 8 ms ago). Will resolve again in 29992 ms
I0905 18:12:55.822265967 208877 subchannel.cc:973] Subchannel 0x7fa4bf929b20: Retry in 997 milliseconds
I0905 18:12:56.820670603 208877 subchannel.cc:998] Failed to connect to channel, retrying
I0905 18:12:56.822812722 208877 subchannel.cc:1034] Connect failed: {"created":"@1567732376.822675728","description":"connect [Errno 111] Connect call failed ('::1', 56765, 0, 0)","file":"third_party/grpc/src/core/lib/iomgr/gevent_util.h","file_line":33,"grpc_status":14}
I0905 18:12:56.822907736 208877 subchannel.cc:973] Subchannel 0x7fa4bf929b20: Retry in 1733 milliseconds
I0905 18:12:58.558091461 208877 subchannel.cc:998] Failed to connect to channel, retrying
I0905 18:12:58.560250142 208877 subchannel.cc:1034] Connect failed: {"created":"@1567732378.560103757","description":"connect [Errno 111] Connect call failed ('::1', 56765, 0, 0)","file":"third_party/grpc/src/core/lib/iomgr/gevent_util.h","file_line":33,"grpc_status":14}
I0905 18:12:58.560346336 208877 subchannel.cc:973] Subchannel 0x7fa4bf929b20: Retry in 2686 milliseconds
I0905 18:13:01.247823225 208877 subchannel.cc:998] Failed to connect to channel, retrying
I0905 18:13:01.249981350 208877 subchannel.cc:1034] Connect failed: {"created":"@1567732381.249818251","description":"connect [Errno 111] Connect call failed ('::1', 56765, 0, 0)","file":"third_party/grpc/src/core/lib/iomgr/gevent_util.h","file_line":33,"grpc_status":14}
I0905 18:13:01.250084149 208877 subchannel.cc:973] Subchannel 0x7fa4bf929b20: Retry in 3804 milliseconds
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment