travis_time:end:16e03b88:start=1433866325342062124,finish=1433866326273836574,duration=931774450
�[0Ktravis_fold:end:before_install.10
�[0Ktravis_time:start:0633faad
�[0K$ rvm use $RUBY_VERSION
�[32mUsing /home/travis/.rvm/gems/ruby-2.1.5�[0m
travis_time:end:0633faad:start=1433866326281546358,finish=1433866330456860941,duration=4175314583
�[0K
�[32;1mThe command "rvm use $RUBY_VERSION" exited with 0.�[0m
travis_time:start:05a68744
�[0K$ gem install bundler
Fetching: bundler-1.10.3.gem
Fetching: bundler-1.10.3.gem ( 7%)
Fetching: bundler-1.10.3.gem ( 13%)
Fetching: bundler-1.10.3.gem ( 20%)
Fetching: bundler-1.10.3.gem ( 26%)
Fetching: bundler-1.10.3.gem ( 33%)
Fetching: bundler-1.10.3.gem ( 39%)
Fetching: bundler-1.10.3.gem ( 46%)
Fetching: bundler-1.10.3.gem ( 53%)
Fetching: bundler-1.10.3.gem ( 59%)
Fetching: bundler-1.10.3.gem ( 66%)
Fetching: bundler-1.10.3.gem ( 72%)
Fetching: bundler-1.10.3.gem ( 79%)
Fetching: bundler-1.10.3.gem ( 85%)
Fetching: bundler-1.10.3.gem ( 92%)
Fetching: bundler-1.10.3.gem ( 98%)
Fetching: bundler-1.10.3.gem (100%)
Fetching: bundler-1.10.3.gem (100%)
Successfully installed bundler-1.10.3
1 gem installed
travis_time:end:05a68744:start=1433866330466453168,finish=1433866333850600769,duration=3384147601
�[0K
�[32;1mThe command "gem install bundler" exited with 0.�[0m
travis_time:start:005ccb02
�[0K$ ./tools/run_tests/prepare_travis.sh
Configuring for disbribution 6356a36510c7c953bcadc005ed23c2e1
gflags-05b155ff59114735ec8cd089f669c4c3d8f59029-opt-prebuilt-6356a36510c7c953bcadc005ed23c2e1.tar.gz ...openssl-3df69d3aefde7671053d4e3c242b228e5d79c83f-opt-prebuilt-6356a36510c7c953bcadc005ed23c2e1.tar.gz ... Found.
protobuf-3e2c8a5dd79481e1d36572cdf65be93514ba6581-opt-prebuilt-6356a36510c7c953bcadc005ed23c2e1.tar.gz ... Found.
zlib-50893291621658f355bc5b4d450a8d06a563053d-opt-prebuilt-6356a36510c7c953bcadc005ed23c2e1.tar.gz ...travis_time:end:005ccb02:start=1433866333859194920,finish=1433866338115514239,duration=4256319319
�[0K
�[32;1mThe command "./tools/run_tests/prepare_travis.sh" exited with 0.�[0m
travis_time:start:02abfd54
�[0K$ if [ ! -z "$USE_GCC" ] ; then export CC=gcc-$USE_GCC ; export CXX=g++-$USE_GCC ; fi
travis_time:end:02abfd54:start=1433866338123295517,finish=1433866338128616337,duration=5320820
�[0K
�[32;1mThe command "if [ ! -z "$USE_GCC" ] ; then export CC=gcc-$USE_GCC ; export CXX=g++-$USE_GCC ; fi" exited with 0.�[0m
travis_time:start:1ca20d63
�[0K$ ./tools/run_tests/run_tests.py -l $TEST -t -j $JOBS -c $CONFIG -s 4.0
�[0G�[2K�[1;30mSTART�[0m: make
�[0G�[2K�[0;32mPASSED�[0m: make [time=9.4sec]
�[0G�[2K�[1;30mSTART�[0m: tools/run_tests/build_python.sh
�[0G�[2K�[0;32mPASSED�[0m: tools/run_tests/build_python.sh [time=12.2sec]
�[0G�[2K�[1;30mSTART�[0m: grpc._adapter._blocking_invocation_inline_service_test
�[0G�[2K�[0;32mPASSED�[0m: grpc._adapter._blocking_invocation_inline_service_test [time=15.2sec]
�[0G�[2K�[1;30mSTART�[0m: grpc._adapter._c_test
�[0G�[2K�[0;32mPASSED�[0m: grpc._adapter._c_test [time=0.2sec]
�[0G�[2K�[1;30mSTART�[0m: grpc._adapter._event_invocation_synchronous_event_service_test
�[0G�[2K�[0;32mPASSED�[0m: grpc._adapter._event_invocation_synchronous_event_service_test [time=16.0sec]
�[0G�[2K�[1;30mSTART�[0m: grpc._adapter._future_invocation_asynchronous_event_service_test
�[0G�[2K�[0;32mPASSED�[0m: grpc._adapter._future_invocation_asynchronous_event_service_test [time=16.5sec]
�[0G�[2K�[1;30mSTART�[0m: grpc._adapter._intermediary_low_test
�[0G�[2K�[0;32mPASSED�[0m: grpc._adapter._intermediary_low_test [time=14.2sec]
�[0G�[2K�[1;30mSTART�[0m: grpc._adapter._links_test
�[0G�[2K�[0;32mPASSED�[0m: grpc._adapter._links_test [time=2.0sec]
�[0G�[2K�[1;30mSTART�[0m: grpc._adapter._lonely_rear_link_test
�[0G�[2K�[0;32mPASSED�[0m: grpc._adapter._lonely_rear_link_test [time=4.3sec]
�[0G�[2K�[1;30mSTART�[0m: grpc._adapter._low_test
�[0G�[2K�[0;32mPASSED�[0m: grpc._adapter._low_test [time=0.6sec]
�[0G�[2K�[1;30mSTART�[0m: grpc.early_adopter.implementations_test
�[0G�[2K�[0;32mPASSED�[0m: grpc.early_adopter.implementations_test [time=4.6sec]
�[0G�[2K�[1;30mSTART�[0m: grpc.framework.base.implementations_test
�[0G�[2K�[0;32mPASSED�[0m: grpc.framework.base.implementations_test [time=0.4sec]
�[0G�[2K�[1;30mSTART�[0m: grpc.framework.face.blocking_invocation_inline_service_test
�[0G�[2K�[0;32mPASSED�[0m: grpc.framework.face.blocking_invocation_inline_service_test [time=19.3sec]
�[0G�[2K�[1;30mSTART�[0m: grpc.framework.face.event_invocation_synchronous_event_service_test
�[0G�[2K�[0;32mPASSED�[0m: grpc.framework.face.event_invocation_synchronous_event_service_test [time=19.0sec]
�[0G�[2K�[1;30mSTART�[0m: grpc.framework.face.future_invocation_asynchronous_event_service_test
�[0G�[2K�[0;32mPASSED�[0m: grpc.framework.face.future_invocation_asynchronous_event_service_test [time=25.3sec]
�[0G�[2K�[1;30mSTART�[0m: grpc.framework.foundation._later_test
�[0G�[2K�[0;32mPASSED�[0m: grpc.framework.foundation._later_test [time=1.1sec]
�[0G�[2K�[1;30mSTART�[0m: grpc.framework.foundation._logging_pool_test
�[0G�[2K�[0;32mPASSED�[0m: grpc.framework.foundation._logging_pool_test [time=0.1sec]
�[0G�[2K�[1;30mSTART�[0m: interop._insecure_interop_test
�[0G�[2K�[0;32mPASSED�[0m: interop._insecure_interop_test [time=29.4sec]
�[0G�[2K�[1;30mSTART�[0m: interop._secure_interop_test
�[0G�[2K�[0;32mPASSED�[0m: interop._secure_interop_test [time=21.8sec]
�[0G�[2K�[1;30mSTART�[0m: test/compiler/python_plugin_test.py
�[0G�[2K
++dirname tools/run_tests/run_python.sh
+cd tools/run_tests/../..
++pwd
+root=/home/travis/build/grpc/grpc
+export LD_LIBRARY_PATH=/home/travis/build/grpc/grpc/libs/opt
+LD_LIBRARY_PATH=/home/travis/build/grpc/grpc/libs/opt
+export DYLD_LIBRARY_PATH=/home/travis/build/grpc/grpc/libs/opt
+DYLD_LIBRARY_PATH=/home/travis/build/grpc/grpc/libs/opt
+source python2.7_virtual_environment/bin/activate
++deactivate nondestructive
++'[' -n '' ']'
++'[' -n '' ']'
++'[' -n /bin/bash -o -n '' ']'
++hash -r
++'[' -n '' ']'
++unset VIRTUAL_ENV
++'[' '!' nondestructive = nondestructive ']'
++VIRTUAL_ENV=/home/travis/build/grpc/grpc/python2.7_virtual_environment
++export VIRTUAL_ENV
++_OLD_VIRTUAL_PATH=/home/travis/.rvm/gems/ruby-2.1.5/bin:/home/travis/.rvm/gems/ruby-2.1.5@global/bin:/home/travis/.rvm/rubies/ruby-2.1.5/bin:/home/travis/.rvm/bin:/home/travis/bin:/home/travis/.local/bin:/home/travis/.gimme/versions/go1.4.1.linux.amd64/bin:/usr/local/phantomjs/bin:/home/travis/.nvm/v0.10.36/bin:./node_modules/.bin:/usr/local/maven-3.2.5/bin:/usr/local/clang-3.4/bin:/home/travis/.gimme/versions/go1.4.1.linux.amd64/bin:/usr/local/phantomjs/bin:./node_modules/.bin:/usr/local/maven-3.2.5/bin:/usr/local/clang-3.4/bin:/home/travis/.gimme/versions/go1.4.1.linux.amd64/bin:/usr/local/phantomjs/bin:./node_modules/.bin:/usr/local/maven-3.2.5/bin:/usr/local/clang-3.4/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
++PATH=/home/travis/build/grpc/grpc/python2.7_virtual_environment/bin:/home/travis/.rvm/gems/ruby-2.1.5/bin:/home/travis/.rvm/gems/ruby-2.1.5@global/bin:/home/travis/.rvm/rubies/ruby-2.1.5/bin:/home/travis/.rvm/bin:/home/travis/bin:/home/travis/.local/bin:/home/travis/.gimme/versions/go1.4.1.linux.amd64/bin:/usr/local/phantomjs/bin:/home/travis/.nvm/v0.10.36/bin:./node_modules/.bin:/usr/local/maven-3.2.5/bin:/usr/local/clang-3.4/bin:/home/travis/.gimme/versions/go1.4.1.linux.amd64/bin:/usr/local/phantomjs/bin:./node_modules/.bin:/usr/local/maven-3.2.5/bin:/usr/local/clang-3.4/bin:/home/travis/.gimme/versions/go1.4.1.linux.amd64/bin:/usr/local/phantomjs/bin:./node_modules/.bin:/usr/local/maven-3.2.5/bin:/usr/local/clang-3.4/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin
++export PATH
++'[' -n '' ']'
++'[' -z '' ']'
++_OLD_VIRTUAL_PS1=
++'[' x '!=' x ']'
+++basename /home/travis/build/grpc/grpc/python2.7_virtual_environment
++'[' python2.7_virtual_environment = __ ']'
+++basename /home/travis/build/grpc/grpc/python2.7_virtual_environment
++PS1='(python2.7_virtual_environment)'
++export PS1
++'[' -n /bin/bash -o -n '' ']'
++hash -r
+python2.7 -B test/compiler/python_plugin_test.py
testFullDuplexCall (main.PythonPluginTest) ... I0609 16:15:49.880827297 11051 server.c:1041] grpc_server_request_call(server=0x303d1c0, call=0x7ffd59b2d9a0, details=0x2b76c20, initial_metadata=0x2b76c50, cq_bound_to_call=0x303cb00, cq_for_notification=0x303cb00, tag=0x2b76c10)
I0609 16:15:49.883771525 11064 call.c:1205] grpc_call_start_batch(call=0x7ffd380029e0, ops=0x7ffd38004500, nops=1, tag=0x7ffd38004480)
I0609 16:15:49.884360852 11064 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:15:49.884457153 11064 call.c:1205] grpc_call_start_batch(call=0x7ffd380029e0, ops=0x7ffd38004b40, nops=1, tag=0x7ffd38004ac0)
I0609 16:15:49.884467405 11064 call.c:1205] ops[0]: RECV_INITIAL_METADATA ptr=0x7ffd38004aa0
I0609 16:15:49.884496547 11064 call.c:1205] grpc_call_start_batch(call=0x7ffd380029e0, ops=0x7ffd38004ed0, nops=1, tag=0x7ffd38004e50)
I0609 16:15:49.884507435 11064 call.c:1205] ops[0]: RECV_STATUS_ON_CLIENT metadata=0x7ffd38004dd0 status=0x7ffd38004df0 details=0x7ffd38004e10
I0609 16:15:49.887492500 11068 call.c:1205] grpc_call_start_batch(call=0x7ffd380029e0, ops=0x7ffd3c004940, nops=1, tag=0x7ffd3c001960)
I0609 16:15:49.887549911 11068 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd3c0056b0
I0609 16:15:49.913683718 11062 completion_queue.c:223] RETURN_EVENT[0x3048eb0]: OP_COMPLETE: tag:0x7ffd38004480 OK
I0609 16:15:49.913870437 11062 completion_queue.c:223] RETURN_EVENT[0x3048eb0]: OP_COMPLETE: tag:0x7ffd3c001960 OK
I0609 16:15:49.914092635 11062 call.c:1205] grpc_call_start_batch(call=0x7ffd380029e0, ops=0x7ffd4c0042e0, nops=1, tag=0x7ffd4c0045e0)
I0609 16:15:49.914108940 11062 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd4c0044e0
I0609 16:15:49.914245446 11062 completion_queue.c:223] RETURN_EVENT[0x3048eb0]: OP_COMPLETE: tag:0x7ffd4c0045e0 OK
I0609 16:15:49.914380485 11062 call.c:1205] grpc_call_start_batch(call=0x7ffd380029e0, ops=0x7ffd4c0046c0, nops=1, tag=0x7ffd4c004270)
I0609 16:15:49.914394418 11062 call.c:1205] ops[0]: SEND_CLOSE_FROM_CLIENT
I0609 16:15:49.914461657 11062 completion_queue.c:223] RETURN_EVENT[0x3048eb0]: OP_COMPLETE: tag:0x7ffd4c004270 OK
I0609 16:15:50.013400448 11061 completion_queue.c:223] RETURN_EVENT[0x303cb00]: OP_COMPLETE: tag:0x2b76c10 OK
I0609 16:15:50.013698322 11061 call.c:1205] grpc_call_start_batch(call=0x7ffd50010270, ops=0x7ffd48002750, nops=1, tag=0x7ffd480026d0)
I0609 16:15:50.013710099 11061 call.c:1205] ops[0]: RECV_CLOSE_ON_SERVER cancelled=0x7ffd480026b0
I0609 16:15:50.013735388 11061 call.c:1205] grpc_call_start_batch(call=0x7ffd50010270, ops=0x7ffd480033e0, nops=1, tag=0x7ffd480036b0)
I0609 16:15:50.013743490 11061 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:15:50.013846220 11061 call.c:1205] grpc_call_start_batch(call=0x7ffd50010270, ops=0x7ffd480037e0, nops=1, tag=0x7ffd48003ca0)
I0609 16:15:50.013856327 11061 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd480037c0
I0609 16:15:50.013953498 11062 completion_queue.c:223] RETURN_EVENT[0x3048eb0]: OP_COMPLETE: tag:0x7ffd38004ac0 OK
I0609 16:15:50.015014841 11062 call.c:1205] grpc_call_start_batch(call=0x7ffd380029e0, ops=0x7ffd4c002010, nops=1, tag=0x7ffd4c004290)
I0609 16:15:50.015051455 11062 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd4c004270
I0609 16:15:50.015519525 11061 server.c:1041] grpc_server_request_call(server=0x303d1c0, call=0x30020e0, details=0x7ffd4800add0, initial_metadata=0x7ffd4800ae00, cq_bound_to_call=0x303cb00, cq_for_notification=0x303cb00, tag=0x7ffd4800adc0)
I0609 16:15:50.015597562 11061 completion_queue.c:223] RETURN_EVENT[0x303cb00]: OP_COMPLETE: tag:0x7ffd480036b0 OK
I0609 16:15:50.015672209 11061 completion_queue.c:223] RETURN_EVENT[0x303cb00]: OP_COMPLETE: tag:0x7ffd48003ca0 OK
I0609 16:15:50.016134546 11061 call.c:1205] grpc_call_start_batch(call=0x7ffd50010270, ops=0x7ffd480033e0, nops=1, tag=0x7ffd48003ca0)
I0609 16:15:50.016152720 11061 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd480033a0
I0609 16:15:50.016491882 11061 completion_queue.c:223] RETURN_EVENT[0x303cb00]: OP_COMPLETE: tag:0x7ffd48003ca0 OK
I0609 16:15:50.016762313 11061 call.c:1205] grpc_call_start_batch(call=0x7ffd50010270, ops=0x7ffd4800ad60, nops=1, tag=0x7ffd48003ca0)
I0609 16:15:50.016772254 11061 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd480037d0
I0609 16:15:50.017617614 11061 completion_queue.c:223] RETURN_EVENT[0x303cb00]: OP_COMPLETE: tag:0x7ffd48003ca0 OK
I0609 16:15:50.019225260 11074 call.c:1205] grpc_call_start_batch(call=0x7ffd50010270, ops=0x7ffd18001e00, nops=1, tag=0x7ffd18001e30)
I0609 16:15:50.019262995 11074 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd180024b0
I0609 16:15:50.019307439 11061 completion_queue.c:223] RETURN_EVENT[0x303cb00]: OP_COMPLETE: tag:0x7ffd18001e30 OK
I0609 16:15:50.019393863 11062 completion_queue.c:223] RETURN_EVENT[0x3048eb0]: OP_COMPLETE: tag:0x7ffd4c004290 OK
I0609 16:15:50.019732698 11062 call.c:1205] grpc_call_start_batch(call=0x7ffd380029e0, ops=0x7ffd4c002090, nops=1, tag=0x7ffd4c004270)
I0609 16:15:50.019746222 11062 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd4c004e10
I0609 16:15:50.022149794 11075 call.c:1205] grpc_call_start_batch(call=0x7ffd50010270, ops=0x7ffd0c001880, nops=1, tag=0x7ffd0c0018b0)
I0609 16:15:50.022187298 11075 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd0c001a60
I0609 16:15:50.022241928 11061 completion_queue.c:223] RETURN_EVENT[0x303cb00]: OP_COMPLETE: tag:0x7ffd0c0018b0 OK
I0609 16:15:50.022385694 11062 completion_queue.c:223] RETURN_EVENT[0x3048eb0]: OP_COMPLETE: tag:0x7ffd4c004270 OK
I0609 16:15:50.025335643 11062 call.c:1205] grpc_call_start_batch(call=0x7ffd380029e0, ops=0x7ffd4c004e10, nops=1, tag=0x7ffd4c004270)
I0609 16:15:50.025768690 11062 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd4c0046e0
I0609 16:15:50.026781971 11075 call.c:1205] grpc_call_start_batch(call=0x7ffd50010270, ops=0x7ffd0c001880, nops=1, tag=0x7ffd0c0018b0)
I0609 16:15:50.026813115 11075 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd0c001a60
I0609 16:15:50.026858767 11061 completion_queue.c:223] RETURN_EVENT[0x303cb00]: OP_COMPLETE: tag:0x7ffd0c0018b0 OK
I0609 16:15:50.026932324 11062 completion_queue.c:223] RETURN_EVENT[0x3048eb0]: OP_COMPLETE: tag:0x7ffd4c004270 OK
I0609 16:15:50.027121046 11062 call.c:1205] grpc_call_start_batch(call=0x7ffd380029e0, ops=0x7ffd4c004e10, nops=1, tag=0x7ffd4c0079b0)
I0609 16:15:50.027132311 11062 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd4c007960
I0609 16:15:50.028599780 11061 call.c:1205] grpc_call_start_batch(call=0x7ffd50010270, ops=0x7ffd48003480, nops=1, tag=0x7ffd48001a40)
I0609 16:15:50.028616683 11061 call.c:1205] ops[0]: SEND_STATUS_FROM_SERVER status=0 details=
I0609 16:15:50.028683791 11061 completion_queue.c:223] RETURN_EVENT[0x303cb00]: OP_COMPLETE: tag:0x7ffd48001a40 OK
I0609 16:15:50.028700253 11062 completion_queue.c:223] RETURN_EVENT[0x3048eb0]: OP_COMPLETE: tag:0x7ffd4c0079b0 OK
I0609 16:15:50.028827306 11061 completion_queue.c:223] RETURN_EVENT[0x303cb00]: OP_COMPLETE: tag:0x7ffd480026d0 OK
I0609 16:15:50.029145604 11062 completion_queue.c:223] RETURN_EVENT[0x3048eb0]: OP_COMPLETE: tag:0x7ffd38004e50 OK
I0609 16:15:50.033579378 11061 completion_queue.c:223] RETURN_EVENT[0x303cb00]: OP_COMPLETE: tag:0x7ffd4800adc0 ERROR
I0609 16:15:50.113644365 11061 completion_queue.c:223] RETURN_EVENT[0x303cb00]: QUEUE_SHUTDOWN
ok
testFullDuplexCallCancelled (main.PythonPluginTest) ... skipped 'TODO(atash,nathaniel): figure out why this flakily hangs forever and fix.'
testFullDuplexCallExpired (main.PythonPluginTest) ... skipped 'TODO(atash,nathaniel): figure out why this flakily hangs forever and fix.'
testFullDuplexCallFailed (main.PythonPluginTest) ... skipped 'TODO(atash,nathaniel): figure out why this hangs forever and fix.'
testHalfDuplexCall (main.PythonPluginTest) ... skipped 'TODO(atash,nathaniel): figure out why this flakily hangs forever and fix.'
testHalfDuplexCallWedged (main.PythonPluginTest) ... I0609 16:15:50.135307169 11051 server.c:1041] grpc_server_request_call(server=0x304ce20, call=0x7ffd59b2dc80, details=0x2bc3820, initial_metadata=0x2bc3850, cq_bound_to_call=0x303e510, cq_for_notification=0x303e510, tag=0x2bc3810)
I0609 16:15:50.140401531 11086 call.c:1205] grpc_call_start_batch(call=0x7ffd0c0025c0, ops=0x7ffd0c001880, nops=1, tag=0x7ffd0c000c70)
I0609 16:15:50.140435310 11086 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:15:50.140583005 11086 call.c:1205] grpc_call_start_batch(call=0x7ffd0c0025c0, ops=0x7ffd0c003930, nops=1, tag=0x7ffd0c0038b0)
I0609 16:15:50.140595661 11086 call.c:1205] ops[0]: RECV_INITIAL_METADATA ptr=0x7ffd0c0011e0
I0609 16:15:50.140623899 11086 call.c:1205] grpc_call_start_batch(call=0x7ffd0c0025c0, ops=0x7ffd0c003aa0, nops=1, tag=0x7ffd0c003a20)
I0609 16:15:50.140638093 11086 call.c:1205] ops[0]: RECV_STATUS_ON_CLIENT metadata=0x7ffd0c0039a0 status=0x7ffd0c0039c0 details=0x7ffd0c0039e0
I0609 16:15:50.142324197 11086 call.c:1205] grpc_call_start_batch(call=0x7ffd0c0025c0, ops=0x7ffd0c003ad0, nops=1, tag=0x7ffd0c0018b0)
I0609 16:15:50.142347133 11086 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd0c003640
I0609 16:15:50.213670753 11088 completion_queue.c:223] RETURN_EVENT[0x30626b0]: OP_COMPLETE: tag:0x7ffd0c000c70 OK
I0609 16:15:50.213838085 11088 completion_queue.c:223] RETURN_EVENT[0x30626b0]: OP_COMPLETE: tag:0x7ffd0c0018b0 OK
I0609 16:15:50.313788317 11083 completion_queue.c:223] RETURN_EVENT[0x303e510]: OP_COMPLETE: tag:0x2bc3810 OK
I0609 16:15:50.314152550 11083 call.c:1205] grpc_call_start_batch(call=0x7ffd5001cb60, ops=0x7ffd04000dc0, nops=1, tag=0x7ffd04000d40)
I0609 16:15:50.314189416 11083 call.c:1205] ops[0]: RECV_CLOSE_ON_SERVER cancelled=0x7ffd04000d20
I0609 16:15:50.314218373 11083 call.c:1205] grpc_call_start_batch(call=0x7ffd5001cb60, ops=0x7ffd04000e90, nops=1, tag=0x7ffd04000f90)
I0609 16:15:50.314228939 11083 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:15:50.314296324 11083 call.c:1205] grpc_call_start_batch(call=0x7ffd5001cb60, ops=0x7ffd040010c0, nops=1, tag=0x7ffd040011c0)
I0609 16:15:50.314308047 11083 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd040010a0
I0609 16:15:50.314422435 11088 completion_queue.c:223] RETURN_EVENT[0x30626b0]: OP_COMPLETE: tag:0x7ffd0c0038b0 OK
I0609 16:15:50.315027342 11088 call.c:1205] grpc_call_start_batch(call=0x7ffd0c0025c0, ops=0x7ffd18000de0, nops=1, tag=0x7ffd180020f0)
I0609 16:15:50.315046588 11088 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd18000dc0
I0609 16:15:50.316019180 11083 server.c:1041] grpc_server_request_call(server=0x304ce20, call=0x3002620, details=0x7ffd04000ed0, initial_metadata=0x7ffd04000f00, cq_bound_to_call=0x303e510, cq_for_notification=0x303e510, tag=0x7ffd04000ec0)
I0609 16:15:50.316069302 11083 completion_queue.c:223] RETURN_EVENT[0x303e510]: OP_COMPLETE: tag:0x7ffd04000f90 OK
I0609 16:15:50.316234759 11083 completion_queue.c:223] RETURN_EVENT[0x303e510]: OP_COMPLETE: tag:0x7ffd040011c0 OK
I0609 16:15:50.316696310 11083 call.c:1205] grpc_call_start_batch(call=0x7ffd5001cb60, ops=0x7ffd04000e90, nops=1, tag=0x7ffd040011c0)
I0609 16:15:50.316711461 11083 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd04000e50
I0609 16:15:51.140554184 11088 completion_queue.c:223] RETURN_EVENT[0x30626b0]: OP_COMPLETE: tag:0x7ffd180020f0 OK
I0609 16:15:51.140562970 11083 completion_queue.c:223] RETURN_EVENT[0x303e510]: OP_COMPLETE: tag:0x7ffd040011c0 OK
I0609 16:15:51.140812307 11088 completion_queue.c:223] RETURN_EVENT[0x30626b0]: OP_COMPLETE: tag:0x7ffd0c003a20 OK
I0609 16:15:51.142734288 11083 completion_queue.c:223] RETURN_EVENT[0x303e510]: OP_COMPLETE: tag:0x7ffd04000d40 OK
I0609 16:15:51.147781818 11083 completion_queue.c:223] RETURN_EVENT[0x303e510]: OP_COMPLETE: tag:0x7ffd04000ec0 ERROR
I0609 16:15:51.147962309 11083 completion_queue.c:223] RETURN_EVENT[0x303e510]: QUEUE_SHUTDOWN
ok
testImportAttributes (main.PythonPluginTest) ... ok
testStreamingInputCall (main.PythonPluginTest) ... skipped 'TODO(atash,nathaniel): figure out why this flakily hangs forever and fix.'
testStreamingInputCallAsync (main.PythonPluginTest) ... I0609 16:15:51.178104172 11051 server.c:1041] grpc_server_request_call(server=0x30648f0, call=0x30026c0, details=0x2bc7d00, initial_metadata=0x2bc7d30, cq_bound_to_call=0x30626b0, cq_for_notification=0x30626b0, tag=0x2bc7cf0)
I0609 16:15:51.181017807 11110 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00ad00, ops=0x7ffd4c006a00, nops=1, tag=0x7ffd4c006980)
I0609 16:15:51.181061641 11110 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:15:51.181170108 11110 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00ad00, ops=0x7ffd4c004e50, nops=1, tag=0x7ffd4c00a470)
I0609 16:15:51.181183220 11110 call.c:1205] ops[0]: RECV_INITIAL_METADATA ptr=0x7ffd4c0085f0
I0609 16:15:51.181219925 11110 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00ad00, ops=0x7ffd4c009290, nops=1, tag=0x7ffd4c009210)
I0609 16:15:51.181234077 11110 call.c:1205] ops[0]: RECV_STATUS_ON_CLIENT metadata=0x7ffd4c00a570 status=0x7ffd4c008510 details=0x7ffd4c008530
I0609 16:15:51.183797289 11112 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00ad00, ops=0x7ffd40003150, nops=1, tag=0x7ffd40001650)
I0609 16:15:51.183822895 11112 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd40001550
I0609 16:15:53.181049162 11108 completion_queue.c:223] RETURN_EVENT[0x3040010]: OP_COMPLETE: tag:0x7ffd4c006980 ERROR
I0609 16:15:53.181570406 11108 completion_queue.c:223] RETURN_EVENT[0x3040010]: OP_COMPLETE: tag:0x7ffd40001650 ERROR
ERROR:root:RPC write not accepted! Event: (Event(kind=<Kind.WRITE_ACCEPTED: <object object at 0x7ffd59add0f0>>, tag=UUID('251649d4-c276-4c91-9efc-12e6fec4f0aa'), write_accepted=False, complete_accepted=None, service_acceptance=None, bytes=None, status=None, metadata=None),)
I0609 16:15:53.183879953 11108 completion_queue.c:223] RETURN_EVENT[0x3040010]: OP_COMPLETE: tag:0x7ffd4c009210 OK
I0609 16:15:53.184156612 11108 completion_queue.c:223] RETURN_EVENT[0x3040010]: OP_COMPLETE: tag:0x7ffd4c00a470 OK
I0609 16:15:53.185607516 11107 completion_queue.c:223] RETURN_EVENT[0x30626b0]: OP_COMPLETE: tag:0x2bc7cf0 ERROR
I0609 16:15:53.213577979 11107 completion_queue.c:223] RETURN_EVENT[0x30626b0]: QUEUE_SHUTDOWN
ERROR
testStreamingInputCallAsyncCancelled (main.PythonPluginTest) ... I0609 16:15:53.298786599 11051 server.c:1041] grpc_server_request_call(server=0x30648f0, call=0x3002780, details=0x2bbc2d0, initial_metadata=0x2bbc300, cq_bound_to_call=0x3040010, cq_for_notification=0x3040010, tag=0x2bbc2c0)
I0609 16:15:53.301482531 11125 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00ad00, ops=0x7ffd4c00a570, nops=1, tag=0x7ffd4c009210)
I0609 16:15:53.301509494 11125 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:15:53.301588136 11125 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00ad00, ops=0x7ffd4c007750, nops=1, tag=0x7ffd4c00a470)
I0609 16:15:53.301602470 11125 call.c:1205] ops[0]: RECV_INITIAL_METADATA ptr=0x7ffd4c001400
I0609 16:15:53.301644323 11125 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00ad00, ops=0x7ffd4c0042e0, nops=1, tag=0x7ffd4c0082b0)
I0609 16:15:53.301658625 11125 call.c:1205] ops[0]: RECV_STATUS_ON_CLIENT metadata=0x7ffd4c006a10 status=0x7ffd4c0017f0 details=0x7ffd4c001810
I0609 16:15:53.303213121 11125 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00ad00, ops=0x7ffd4c000a30, nops=1, tag=0x7ffd4c006740)
I0609 16:15:53.303229981 11125 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd4c006640
I0609 16:15:54.301544149 11123 completion_queue.c:223] RETURN_EVENT[0x3079cb0]: OP_COMPLETE: tag:0x7ffd4c009210 ERROR
I0609 16:15:54.301717373 11123 completion_queue.c:223] RETURN_EVENT[0x3079cb0]: OP_COMPLETE: tag:0x7ffd4c006740 ERROR
I0609 16:15:54.301939653 11123 completion_queue.c:223] RETURN_EVENT[0x3079cb0]: OP_COMPLETE: tag:0x7ffd4c0082b0 OK
I0609 16:15:54.302111379 11123 completion_queue.c:223] RETURN_EVENT[0x3079cb0]: OP_COMPLETE: tag:0x7ffd4c00a470 OK
I0609 16:15:54.303336520 11122 completion_queue.c:223] RETURN_EVENT[0x3040010]: OP_COMPLETE: tag:0x2bbc2c0 ERROR
I0609 16:15:54.334212298 11122 completion_queue.c:223] RETURN_EVENT[0x3040010]: QUEUE_SHUTDOWN
ok
testStreamingInputCallAsyncExpired (main.PythonPluginTest) ... I0609 16:15:54.349488191 11051 server.c:1041] grpc_server_request_call(server=0x30712a0, call=0x3002960, details=0x2de16c0, initial_metadata=0x2de16f0, cq_bound_to_call=0x3079cb0, cq_for_notification=0x3079cb0, tag=0x2de16b0)
I0609 16:15:54.352240763 11140 call.c:1205] grpc_call_start_batch(call=0x7ffd48010f00, ops=0x7ffd48001b00, nops=1, tag=0x7ffd4800adc0)
I0609 16:15:54.352268221 11140 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:15:54.352352896 11140 call.c:1205] grpc_call_start_batch(call=0x7ffd48010f00, ops=0x7ffd48007ad0, nops=1, tag=0x7ffd48008030)
I0609 16:15:54.352369140 11140 call.c:1205] ops[0]: RECV_INITIAL_METADATA ptr=0x7ffd4800dce0
I0609 16:15:54.352416761 11140 call.c:1205] grpc_call_start_batch(call=0x7ffd48010f00, ops=0x7ffd4800eb20, nops=1, tag=0x7ffd4800eaa0)
I0609 16:15:54.352435330 11140 call.c:1205] ops[0]: RECV_STATUS_ON_CLIENT metadata=0x7ffd48010270 status=0x7ffd48010290 details=0x7ffd480102b0
I0609 16:15:54.355633929 11140 call.c:1205] grpc_call_start_batch(call=0x7ffd48010f00, ops=0x7ffd4800fd00, nops=1, tag=0x7ffd4800a0d0)
I0609 16:15:54.355654483 11140 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd48000d00
I0609 16:15:54.452259025 11138 completion_queue.c:223] RETURN_EVENT[0x306c770]: OP_COMPLETE: tag:0x7ffd4800adc0 ERROR
I0609 16:15:54.452461099 11138 completion_queue.c:223] RETURN_EVENT[0x306c770]: OP_COMPLETE: tag:0x7ffd4800a0d0 ERROR
ERROR:root:RPC write not accepted! Event: (Event(kind=<Kind.WRITE_ACCEPTED: <object object at 0x7ffd59add0f0>>, tag=UUID('2958fcde-be64-460c-bd08-3411d0a5bb96'), write_accepted=False, complete_accepted=None, service_acceptance=None, bytes=None, status=None, metadata=None),)
I0609 16:15:54.454920309 11138 completion_queue.c:223] RETURN_EVENT[0x306c770]: OP_COMPLETE: tag:0x7ffd4800eaa0 OK
I0609 16:15:54.455192131 11138 completion_queue.c:223] RETURN_EVENT[0x306c770]: OP_COMPLETE: tag:0x7ffd48008030 OK
I0609 16:15:54.456772651 11137 completion_queue.c:223] RETURN_EVENT[0x3079cb0]: OP_COMPLETE: tag:0x2de16b0 ERROR
I0609 16:15:54.513574645 11137 completion_queue.c:223] RETURN_EVENT[0x3079cb0]: QUEUE_SHUTDOWN
ok
testStreamingInputCallAsyncFailed (main.PythonPluginTest) ... I0609 16:15:54.566921717 11051 server.c:1041] grpc_server_request_call(server=0x30712a0, call=0x30026c0, details=0x297cd40, initial_metadata=0x297cd70, cq_bound_to_call=0x306c770, cq_for_notification=0x306c770, tag=0x297cd30)
I0609 16:15:54.569452436 11155 call.c:1205] grpc_call_start_batch(call=0x7ffd0400b020, ops=0x7ffd04006ee0, nops=1, tag=0x7ffd04000da0)
I0609 16:15:54.569475499 11155 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:15:54.569558530 11155 call.c:1205] grpc_call_start_batch(call=0x7ffd0400b020, ops=0x7ffd0400a8a0, nops=1, tag=0x7ffd0400a820)
I0609 16:15:54.569571543 11155 call.c:1205] ops[0]: RECV_INITIAL_METADATA ptr=0x7ffd040008f0
I0609 16:15:54.569607582 11155 call.c:1205] grpc_call_start_batch(call=0x7ffd0400b020, ops=0x7ffd0400aa10, nops=1, tag=0x7ffd0400a990)
I0609 16:15:54.569622836 11155 call.c:1205] ops[0]: RECV_STATUS_ON_CLIENT metadata=0x7ffd0400a910 status=0x7ffd0400a930 details=0x7ffd0400a950
I0609 16:15:54.571624761 11153 call.c:1205] grpc_call_start_batch(call=0x7ffd0400b020, ops=0x7ffd1c002d60, nops=1, tag=0x7ffd1c000de0)
I0609 16:15:54.571646321 11153 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd1c000ce0
I0609 16:15:54.669520858 11157 completion_queue.c:223] RETURN_EVENT[0x306d3c0]: OP_COMPLETE: tag:0x7ffd04000da0 ERROR
I0609 16:15:54.670910117 11157 completion_queue.c:223] RETURN_EVENT[0x306d3c0]: OP_COMPLETE: tag:0x7ffd1c000de0 ERROR
I0609 16:15:54.671225808 11157 completion_queue.c:223] RETURN_EVENT[0x306d3c0]: OP_COMPLETE: tag:0x7ffd0400a990 OK
I0609 16:15:54.671411235 11157 completion_queue.c:223] RETURN_EVENT[0x306d3c0]: OP_COMPLETE: tag:0x7ffd0400a820 OK
I0609 16:15:54.672691527 11152 completion_queue.c:223] RETURN_EVENT[0x306c770]: OP_COMPLETE: tag:0x297cd30 ERROR
I0609 16:15:54.713519146 11152 completion_queue.c:223] RETURN_EVENT[0x306c770]: QUEUE_SHUTDOWN
ok
testStreamingOutputCall (main.PythonPluginTest) ... I0609 16:15:54.783989108 11051 server.c:1041] grpc_server_request_call(server=0x30712a0, call=0x301c340, details=0x2e85600, initial_metadata=0x2e85630, cq_bound_to_call=0x3077390, cq_for_notification=0x3077390, tag=0x2e855f0)
I0609 16:15:54.795342919 11170 call.c:1205] grpc_call_start_batch(call=0x7ffd14005f80, ops=0x7ffd14001e40, nops=1, tag=0x7ffd14000ed0)
I0609 16:15:54.795387257 11170 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:15:54.795486744 11170 call.c:1205] grpc_call_start_batch(call=0x7ffd14005f80, ops=0x7ffd14005720, nops=1, tag=0x7ffd140012d0)
I0609 16:15:54.795498272 11170 call.c:1205] ops[0]: RECV_INITIAL_METADATA ptr=0x7ffd140012b0
I0609 16:15:54.795526110 11170 call.c:1205] grpc_call_start_batch(call=0x7ffd14005f80, ops=0x7ffd14000f50, nops=1, tag=0x7ffd140032a0)
I0609 16:15:54.795538569 11170 call.c:1205] ops[0]: RECV_STATUS_ON_CLIENT metadata=0x7ffd14003220 status=0x7ffd14003240 details=0x7ffd14003260
I0609 16:15:54.795823419 11170 call.c:1205] grpc_call_start_batch(call=0x7ffd14005f80, ops=0x7ffd14003390, nops=1, tag=0x7ffd14004500)
I0609 16:15:54.795835431 11170 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd14004400
I0609 16:15:55.795345348 11168 completion_queue.c:223] RETURN_EVENT[0x3092460]: OP_COMPLETE: tag:0x7ffd14000ed0 ERROR
I0609 16:15:55.795490307 11168 completion_queue.c:223] RETURN_EVENT[0x3092460]: OP_COMPLETE: tag:0x7ffd14004500 ERROR
I0609 16:15:55.795703889 11168 completion_queue.c:223] RETURN_EVENT[0x3092460]: OP_COMPLETE: tag:0x7ffd140032a0 OK
I0609 16:15:55.795877494 11168 completion_queue.c:223] RETURN_EVENT[0x3092460]: OP_COMPLETE: tag:0x7ffd140012d0 OK
I0609 16:15:55.797894479 11167 completion_queue.c:223] RETURN_EVENT[0x3077390]: OP_COMPLETE: tag:0x2e855f0 ERROR
I0609 16:15:55.813571921 11167 completion_queue.c:223] RETURN_EVENT[0x3077390]: QUEUE_SHUTDOWN
ERROR
testStreamingOutputCallCancelled (main.PythonPluginTest) ... skipped 'TODO(atash,nathaniel): figure out why this flakily hangs forever and fix.'
testStreamingOutputCallExpired (main.PythonPluginTest) ... skipped 'TODO(atash,nathaniel): figure out why this flakily hangs forever and fix.'
testStreamingOutputCallFailed (main.PythonPluginTest) ... skipped 'TODO(atash,nathaniel): figure out why this times out instead of raising the proper error.'
testUnaryCall (main.PythonPluginTest) ... I0609 16:15:55.832150017 11051 server.c:1041] grpc_server_request_call(server=0x308af90, call=0x301c2c0, details=0x3069390, initial_metadata=0x30693c0, cq_bound_to_call=0x3092460, cq_for_notification=0x3092460, tag=0x3069380)
I0609 16:15:55.835393828 11184 call.c:1205] grpc_call_start_batch(call=0x7ffd3800bef0, ops=0x7ffd38003790, nops=1, tag=0x7ffd3800ab90)
I0609 16:15:55.835451477 11184 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:15:55.835573702 11184 call.c:1205] grpc_call_start_batch(call=0x7ffd3800bef0, ops=0x7ffd3800b3d0, nops=1, tag=0x7ffd3800b350)
I0609 16:15:55.835586394 11184 call.c:1205] ops[0]: RECV_INITIAL_METADATA ptr=0x7ffd3800b330
I0609 16:15:55.835616841 11184 call.c:1205] grpc_call_start_batch(call=0x7ffd3800bef0, ops=0x7ffd3800b590, nops=1, tag=0x7ffd3800b510)
I0609 16:15:55.835630197 11184 call.c:1205] ops[0]: RECV_STATUS_ON_CLIENT metadata=0x7ffd3800b490 status=0x7ffd3800b4b0 details=0x7ffd3800b4d0
I0609 16:15:55.835833097 11184 call.c:1205] grpc_call_start_batch(call=0x7ffd3800bef0, ops=0x7ffd3800b5c0, nops=1, tag=0x7ffd3800a360)
I0609 16:15:55.835847245 11184 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd3800a260
I0609 16:15:56.835394320 11182 completion_queue.c:223] RETURN_EVENT[0x3085920]: OP_COMPLETE: tag:0x7ffd3800ab90 ERROR
I0609 16:15:56.835768547 11182 completion_queue.c:223] RETURN_EVENT[0x3085920]: OP_COMPLETE: tag:0x7ffd3800a360 ERROR
I0609 16:15:56.836018167 11182 completion_queue.c:223] RETURN_EVENT[0x3085920]: OP_COMPLETE: tag:0x7ffd3800b510 OK
I0609 16:15:56.836540969 11182 completion_queue.c:223] RETURN_EVENT[0x3085920]: OP_COMPLETE: tag:0x7ffd3800b350 OK
I0609 16:15:56.839983805 11181 completion_queue.c:223] RETURN_EVENT[0x3092460]: OP_COMPLETE: tag:0x3069380 ERROR
I0609 16:15:56.913579923 11181 completion_queue.c:223] RETURN_EVENT[0x3092460]: QUEUE_SHUTDOWN
ERROR
testUnaryCallAsync (main.PythonPluginTest) ... I0609 16:15:56.954053557 11051 server.c:1041] grpc_server_request_call(server=0x308af90, call=0x301c320, details=0x2bc7d00, initial_metadata=0x2bc7d30, cq_bound_to_call=0x3089b80, cq_for_notification=0x3089b80, tag=0x2bc7cf0)
I0609 16:15:56.966684463 11198 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00f740, ops=0x7ffd4c0042e0, nops=1, tag=0x7ffd4c009210)
I0609 16:15:56.966739708 11198 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:15:56.966859352 11198 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00f740, ops=0x7ffd4c007750, nops=1, tag=0x7ffd4c0069a0)
I0609 16:15:56.966871415 11198 call.c:1205] ops[0]: RECV_INITIAL_METADATA ptr=0x7ffd4c001050
I0609 16:15:56.966899407 11198 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00f740, ops=0x7ffd4c002950, nops=1, tag=0x7ffd4c00a470)
I0609 16:15:56.966916647 11198 call.c:1205] ops[0]: RECV_STATUS_ON_CLIENT metadata=0x7ffd4c000a00 status=0x7ffd4c000a20 details=0x7ffd4c000a40
I0609 16:15:56.967088302 11198 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00f740, ops=0x7ffd4c000a80, nops=1, tag=0x7ffd4c008320)
I0609 16:15:56.967100704 11198 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd4c00d230
E0609 16:15:57.567751540 11055 tcp_client_posix.c:148] socket error: connection refused
E0609 16:15:57.567948949 11055 tcp_client_posix.c:148] socket error: connection refused
E0609 16:15:57.567980151 11055 tcp_client_posix.c:148] socket error: connection refused
E0609 16:15:57.713177538 11055 tcp_client_posix.c:148] socket error: connection refused
E0609 16:15:57.713303236 11055 tcp_client_posix.c:148] socket error: connection refused
E0609 16:15:57.713322709 11055 tcp_client_posix.c:148] socket error: connection refused
I0609 16:15:57.713689126 11200 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd4c009210 OK
I0609 16:15:57.713813325 11200 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd4c008320 OK
I0609 16:15:57.714039318 11200 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00f740, ops=0x7ffd34005b80, nops=1, tag=0x7ffd34009cf0)
I0609 16:15:57.714055779 11200 call.c:1205] ops[0]: SEND_CLOSE_FROM_CLIENT
I0609 16:15:57.714126977 11200 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd34009cf0 OK
I0609 16:15:57.913330786 11195 completion_queue.c:223] RETURN_EVENT[0x3089b80]: OP_COMPLETE: tag:0x2bc7cf0 OK
I0609 16:15:57.913682484 11195 call.c:1205] grpc_call_start_batch(call=0x7ffd50027660, ops=0x7ffd40001740, nops=1, tag=0x7ffd40000ce0)
I0609 16:15:57.913699019 11195 call.c:1205] ops[0]: RECV_CLOSE_ON_SERVER cancelled=0x7ffd40002510
I0609 16:15:57.913729047 11195 call.c:1205] grpc_call_start_batch(call=0x7ffd50027660, ops=0x7ffd400018f0, nops=1, tag=0x7ffd40000e80)
I0609 16:15:57.913740133 11195 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:15:57.913859569 11195 call.c:1205] grpc_call_start_batch(call=0x7ffd50027660, ops=0x7ffd40000c50, nops=1, tag=0x7ffd400032a0)
I0609 16:15:57.913873758 11195 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd40002720
I0609 16:15:57.913975557 11200 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd4c0069a0 OK
I0609 16:15:57.914589737 11200 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00f740, ops=0x7ffd34001a90, nops=1, tag=0x7ffd340058d0)
I0609 16:15:57.914604597 11200 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd34005ba0
I0609 16:15:57.915449969 11195 server.c:1041] grpc_server_request_call(server=0x308af90, call=0x301c3a0, details=0x7ffd400009a0, initial_metadata=0x7ffd400009d0, cq_bound_to_call=0x3089b80, cq_for_notification=0x3089b80, tag=0x7ffd40000990)
I0609 16:15:57.915508443 11195 completion_queue.c:223] RETURN_EVENT[0x3089b80]: OP_COMPLETE: tag:0x7ffd40000e80 OK
I0609 16:15:57.915724231 11195 completion_queue.c:223] RETURN_EVENT[0x3089b80]: OP_COMPLETE: tag:0x7ffd400032a0 OK
I0609 16:15:57.915915955 11195 call.c:1205] grpc_call_start_batch(call=0x7ffd50027660, ops=0x7ffd400018f0, nops=1, tag=0x7ffd400032a0)
I0609 16:15:57.915934263 11195 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd40000f30
I0609 16:15:57.916857324 11195 completion_queue.c:223] RETURN_EVENT[0x3089b80]: OP_COMPLETE: tag:0x7ffd400032a0 OK
E0609 16:15:58.613918177 11055 tcp_client_posix.c:148] socket error: connection refused
E0609 16:15:58.714799975 11055 tcp_client_posix.c:148] socket error: connection refused
E0609 16:15:58.714846506 11055 tcp_client_posix.c:148] socket error: connection refused
E0609 16:15:58.714938894 11055 tcp_client_posix.c:148] socket error: connection refused
E0609 16:15:58.913171945 11055 tcp_client_posix.c:148] socket error: connection refused
E0609 16:15:58.913224661 11055 tcp_client_posix.c:148] socket error: connection refused
I0609 16:15:58.918142024 11203 call.c:1205] grpc_call_start_batch(call=0x7ffd50027660, ops=0x7ffd1c0035d0, nops=1, tag=0x7ffd1c004ff0)
I0609 16:15:58.918202985 11203 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd1c002cc0
I0609 16:15:58.918287287 11195 completion_queue.c:223] RETURN_EVENT[0x3089b80]: OP_COMPLETE: tag:0x7ffd1c004ff0 OK
I0609 16:15:58.918364393 11200 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd340058d0 OK
I0609 16:15:58.918906016 11200 call.c:1205] grpc_call_start_batch(call=0x7ffd4c00f740, ops=0x7ffd34001a90, nops=1, tag=0x7ffd340058d0)
I0609 16:15:58.918922172 11200 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd34005ba0
I0609 16:15:58.920312647 11203 call.c:1205] grpc_call_start_batch(call=0x7ffd50027660, ops=0x7ffd1c0035a0, nops=1, tag=0x7ffd1c004ff0)
I0609 16:15:58.920331509 11203 call.c:1205] ops[0]: SEND_STATUS_FROM_SERVER status=0 details=
I0609 16:15:58.920379299 11195 completion_queue.c:223] RETURN_EVENT[0x3089b80]: OP_COMPLETE: tag:0x7ffd1c004ff0 OK
I0609 16:15:58.920659028 11195 completion_queue.c:223] RETURN_EVENT[0x3089b80]: OP_COMPLETE: tag:0x7ffd40000ce0 OK
I0609 16:15:58.921880929 11200 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd340058d0 OK
I0609 16:15:58.922083119 11200 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd4c00a470 OK
I0609 16:15:58.928007506 11195 completion_queue.c:223] RETURN_EVENT[0x3089b80]: OP_COMPLETE: tag:0x7ffd40000990 ERROR
I0609 16:15:58.967170848 11195 completion_queue.c:223] RETURN_EVENT[0x3089b80]: QUEUE_SHUTDOWN
ok
testUnaryCallAsyncCancelled (main.PythonPluginTest) ... skipped 'TODO(atash,nathaniel): figure out why this flakily hangs forever and fix.'
testUnaryCallAsyncExpired (main.PythonPluginTest) ... I0609 16:15:59.986940822 11051 server.c:1041] grpc_server_request_call(server=0x306dab0, call=0x301c680, details=0x2bda960, initial_metadata=0x2bda990, cq_bound_to_call=0x3092460, cq_for_notification=0x3092460, tag=0x2bda950)
I0609 16:15:59.990266095 11223 call.c:1205] grpc_call_start_batch(call=0x7ffd2000a960, ops=0x7ffd200040c0, nops=1, tag=0x7ffd20008470)
I0609 16:15:59.990305079 11223 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:15:59.990417414 11223 call.c:1205] grpc_call_start_batch(call=0x7ffd2000a960, ops=0x7ffd20004300, nops=1, tag=0x7ffd20002960)
I0609 16:15:59.990432043 11223 call.c:1205] ops[0]: RECV_INITIAL_METADATA ptr=0x7ffd20000b10
I0609 16:15:59.990468539 11223 call.c:1205] grpc_call_start_batch(call=0x7ffd2000a960, ops=0x7ffd200008c0, nops=1, tag=0x7ffd20002ae0)
I0609 16:15:59.990486918 11223 call.c:1205] ops[0]: RECV_STATUS_ON_CLIENT metadata=0x7ffd20002a60 status=0x7ffd20002a80 details=0x7ffd20002aa0
I0609 16:15:59.990703118 11223 call.c:1205] grpc_call_start_batch(call=0x7ffd2000a960, ops=0x7ffd20007e70, nops=1, tag=0x7ffd20002bd0)
I0609 16:15:59.990717440 11223 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd20008ba0
I0609 16:16:00.013624670 11221 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd20008470 OK
I0609 16:16:00.013797515 11221 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd20002bd0 OK
I0609 16:16:00.014022409 11221 call.c:1205] grpc_call_start_batch(call=0x7ffd2000a960, ops=0x7ffd1c005110, nops=1, tag=0x7ffd1c004ff0)
I0609 16:16:00.014036587 11221 call.c:1205] ops[0]: SEND_CLOSE_FROM_CLIENT
I0609 16:16:00.014137321 11221 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd1c004ff0 OK
I0609 16:16:00.090256415 11221 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd20002960 OK
I0609 16:16:00.090567895 11221 call.c:1205] grpc_call_start_batch(call=0x7ffd2000a960, ops=0x7ffd1c004670, nops=1, tag=0x7ffd1c002d30)
I0609 16:16:00.090585261 11221 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd1c000f00
I0609 16:16:00.090634428 11221 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd20002ae0 OK
I0609 16:16:00.093600558 11221 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd1c002d30 OK
I0609 16:16:00.095790114 11220 completion_queue.c:223] RETURN_EVENT[0x3092460]: OP_COMPLETE: tag:0x2bda950 ERROR
I0609 16:16:00.098678075 11220 completion_queue.c:223] RETURN_EVENT[0x3092460]: QUEUE_SHUTDOWN
ok
testUnaryCallAsyncFailed (main.PythonPluginTest) ... I0609 16:16:00.127242113 11051 server.c:1041] grpc_server_request_call(server=0x306dab0, call=0x301c960, details=0x2bde5e0, initial_metadata=0x2bde610, cq_bound_to_call=0x309bd90, cq_for_notification=0x309bd90, tag=0x2bde5d0)
I0609 16:16:00.130791341 11237 call.c:1205] grpc_call_start_batch(call=0x7ffd1c007170, ops=0x7ffd1c0058c0, nops=1, tag=0x7ffd1c004ff0)
I0609 16:16:00.130832307 11237 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:16:00.130942388 11237 call.c:1205] grpc_call_start_batch(call=0x7ffd1c007170, ops=0x7ffd1c005c90, nops=1, tag=0x7ffd1c002d50)
I0609 16:16:00.130955534 11237 call.c:1205] ops[0]: RECV_INITIAL_METADATA ptr=0x7ffd1c005c70
I0609 16:16:00.130980495 11237 call.c:1205] grpc_call_start_batch(call=0x7ffd1c007170, ops=0x7ffd1c005d10, nops=1, tag=0x7ffd1c006200)
I0609 16:16:00.130994515 11237 call.c:1205] ops[0]: RECV_STATUS_ON_CLIENT metadata=0x7ffd1c001880 status=0x7ffd1c0061a0 details=0x7ffd1c0061c0
I0609 16:16:00.131229006 11237 call.c:1205] grpc_call_start_batch(call=0x7ffd1c007170, ops=0x7ffd1c006620, nops=1, tag=0x7ffd1c0065a0)
I0609 16:16:00.131241707 11237 call.c:1205] ops[0]: SEND_MESSAGE ptr=0x7ffd1c0064a0
I0609 16:16:00.213579308 11235 completion_queue.c:223] RETURN_EVENT[0x3092460]: OP_COMPLETE: tag:0x7ffd1c004ff0 OK
I0609 16:16:00.213660330 11234 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x2bde5d0 OK
I0609 16:16:00.213773819 11235 completion_queue.c:223] RETURN_EVENT[0x3092460]: OP_COMPLETE: tag:0x7ffd1c0065a0 OK
I0609 16:16:00.214137150 11234 call.c:1205] grpc_call_start_batch(call=0x7ffd5002abf0, ops=0x7ffd140008c0, nops=1, tag=0x7ffd14005660)
I0609 16:16:00.214163822 11234 call.c:1205] ops[0]: RECV_CLOSE_ON_SERVER cancelled=0x7ffd14005560
I0609 16:16:00.214195807 11234 call.c:1205] grpc_call_start_batch(call=0x7ffd5002abf0, ops=0x7ffd14005720, nops=1, tag=0x7ffd14004080)
I0609 16:16:00.214208324 11234 call.c:1205] ops[0]: SEND_INITIAL_METADATA
I0609 16:16:00.214323577 11234 call.c:1205] grpc_call_start_batch(call=0x7ffd5002abf0, ops=0x7ffd14000e40, nops=1, tag=0x7ffd140044d0)
I0609 16:16:00.214339052 11234 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd14001780
I0609 16:16:00.215208415 11235 call.c:1205] grpc_call_start_batch(call=0x7ffd1c007170, ops=0x7ffd30001520, nops=1, tag=0x7ffd30000f10)
I0609 16:16:00.215243056 11235 call.c:1205] ops[0]: SEND_CLOSE_FROM_CLIENT
I0609 16:16:00.215365135 11235 completion_queue.c:223] RETURN_EVENT[0x3092460]: OP_COMPLETE: tag:0x7ffd30000f10 OK
I0609 16:16:00.216067708 11235 completion_queue.c:223] RETURN_EVENT[0x3092460]: OP_COMPLETE: tag:0x7ffd1c002d50 OK
I0609 16:16:00.216236689 11235 call.c:1205] grpc_call_start_batch(call=0x7ffd1c007170, ops=0x7ffd30001410, nops=1, tag=0x7ffd30003460)
I0609 16:16:00.216250832 11235 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd300013f0
I0609 16:16:00.216677223 11234 server.c:1041] grpc_server_request_call(server=0x306dab0, call=0x301c3c0, details=0x7ffd1400a9a0, initial_metadata=0x7ffd1400a9d0, cq_bound_to_call=0x309bd90, cq_for_notification=0x309bd90, tag=0x7ffd1400a990)
I0609 16:16:00.216732981 11234 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd14004080 OK
I0609 16:16:00.216856216 11234 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd140044d0 OK
I0609 16:16:00.217016203 11234 call.c:1205] grpc_call_start_batch(call=0x7ffd5002abf0, ops=0x7ffd14005720, nops=1, tag=0x7ffd140044d0)
I0609 16:16:00.217031001 11234 call.c:1205] ops[0]: RECV_MESSAGE ptr=0x7ffd14001340
I0609 16:16:00.218217493 11234 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd140044d0 OK
ERROR:root:Exception during ingestion!
Traceback (most recent call last):
File "/home/travis/build/grpc/grpc/python2.7_virtual_environment/local/lib/python2.7/site-packages/grpc/framework/foundation/callable_util.py", line 69, in _call_logging_exceptions
return _EasyOutcome(Outcome.Kind.RETURNED, behavior(_args, *_kwargs), None)
File "/home/travis/build/grpc/grpc/python2.7_virtual_environment/local/lib/python2.7/site-packages/grpc/framework/base/_ingestion.py", line 198, in moar
self._consumer.consume(payload)
File "/home/travis/build/grpc/grpc/python2.7_virtual_environment/local/lib/python2.7/site-packages/grpc/framework/foundation/stream_util.py", line 48, in consume
self._downstream.consume(self._transformation(value))
File "/home/travis/build/grpc/grpc/python2.7_virtual_environment/local/lib/python2.7/site-packages/grpc/framework/face/_service.py", line 108, in
lambda request: method(request, rpc_context), response_consumer)
File "/home/travis/build/grpc/grpc/python2.7_virtual_environment/local/lib/python2.7/site-packages/grpc/framework/alpha/_face_utilities.py", line 150, in service
request, _reexport.rpc_context(face_rpc_context))
File "/home/travis/build/grpc/grpc/python2.7_virtual_environment/local/lib/python2.7/site-packages/grpc/framework/alpha/utilities.py", line 75, in service_unary_unary
return self._unary_unary(request, context)
File "test/compiler/python_plugin_test.py", line 164, in UnaryCall
File "test/compiler/python_plugin_test.py", line 95, in UnaryCall
File "test/compiler/python_plugin_test.py", line 86, in _control
ValueError
I0609 16:16:00.222602032 11235 completion_queue.c:223] RETURN_EVENT[0x3092460]: OP_COMPLETE: tag:0x7ffd30003460 OK
I0609 16:16:00.222609104 11234 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd14005660 OK
I0609 16:16:00.223083780 11235 completion_queue.c:223] RETURN_EVENT[0x3092460]: OP_COMPLETE: tag:0x7ffd1c006200 OK
I0609 16:16:00.226808425 11234 completion_queue.c:223] RETURN_EVENT[0x309bd90]: OP_COMPLETE: tag:0x7ffd1400a990 ERROR
I0609 16:16:00.257937383 11234 completion_queue.c:223] RETURN_EVENT[0x309bd90]: QUEUE_SHUTDOWN
ok
testUpDown (main.PythonPluginTest) ... I0609 16:16:00.329026930 11051 server.c:1041] grpc_server_request_call(server=0x3094bb0, call=0x301ce40, details=0x3069390, initial_metadata=0x30693c0, cq_bound_to_call=0x3069740, cq_for_notification=0x3069740, tag=0x3069380)
I0609 16:16:00.331560137 11254 completion_queue.c:223] RETURN_EVENT[0x3069740]: OP_COMPLETE: tag:0x3069380 ERROR
I0609 16:16:00.357972185 11254 completion_queue.c:223] RETURN_EVENT[0x3069740]: QUEUE_SHUTDOWN
ok

ERROR: testStreamingInputCallAsync (main.PythonPluginTest)

Traceback (most recent call last):
File "test/compiler/python_plugin_test.py", line 391, in testStreamingInputCallAsync
File "/home/travis/build/grpc/grpc/python2.7_virtual_environment/local/lib/python2.7/site-packages/grpc/framework/alpha/_reexport.py", line 96, in result
raise _reexport_error(e)
ExpirationError

ERROR: testStreamingOutputCall (main.PythonPluginTest)

Traceback (most recent call last):
File "test/compiler/python_plugin_test.py", line 330, in testStreamingOutputCall
File "/home/travis/build/grpc/grpc/python2.7_virtual_environment/local/lib/python2.7/site-packages/grpc/framework/alpha/_reexport.py", line 129, in next
return _call_reexporting_errors(self._face_cancellable_iterator.next)
File "/home/travis/build/grpc/grpc/python2.7_virtual_environment/local/lib/python2.7/site-packages/grpc/framework/alpha/_reexport.py", line 113, in _call_reexporting_errors
raise _reexport_error(e)
ExpirationError

ERROR: testUnaryCall (main.PythonPluginTest)

Traceback (most recent call last):
File "test/compiler/python_plugin_test.py", line 275, in testUnaryCall
File "/home/travis/build/grpc/grpc/python2.7_virtual_environment/local/lib/python2.7/site-packages/grpc/framework/alpha/_reexport.py", line 158, in call
self._underlying, request, timeout)
File "/home/travis/build/grpc/grpc/python2.7_virtual_environment/local/lib/python2.7/site-packages/grpc/framework/alpha/_reexport.py", line 113, in _call_reexporting_errors
raise _reexport_error(e)
ExpirationError

Ran 22 tests in 10.656s

FAILED (errors=3, skipped=9)
D0609 16:16:00.434060925 11051 iomgr.c:120] Waiting for 1 iomgr objects to be destroyed and executing final callbacks
�[0;31mFAILED�[0m: test/compiler/python_plugin_test.py [ret=1, pid=11044]
�[0G�[2K�[0;31mFAILED�[0m: Some tests failed
travis_time:end:1ca20d63:start=1433866338135987638,finish=1433866560535138571,duration=222399150933
�[0K
�[31;1mThe command "./tools/run_tests/run_tests.py -l $TEST -t -j $JOBS -c $CONFIG -s 4.0" exited with 2.�[0m

Done. Your build exited with 1.