Back to build
Raw log | Switch to full mode | Login

Set PYTHONPATH: /b/swarming/w/ir/kitchen-checkout/build/scripts:/b/swarming/w/ir/kitchen-checkout/build/site_config:/b/swarming/w/ir/kitchen-checkout/build/third_party:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_8_4p1:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_slave_8_4:/b/swarming/w/ir/kitchen-checkout/build/third_party/coverage-3.7.1:/b/swarming/w/ir/kitchen-checkout/build/third_party/decorator_3_3_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/google_api_python_client:/b/swarming/w/ir/kitchen-checkout/build/third_party/httplib2/python2:/b/swarming/w/ir/kitchen-checkout/build/third_party/infra_libs:/b/swarming/w/ir/kitchen-checkout/build/third_party/jinja2:/b/swarming/w/ir/kitchen-checkout/build/third_party/markupsafe:/b/swarming/w/ir/kitchen-checkout/build/third_party/oauth2client:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1-modules:/b/swarming/w/ir/kitchen-checkout/build/third_party/python-rsa:/b/swarming/w/ir/kitchen-checkout/build/third_party/requests_2_10_0:/b/swarming/w/ir/kitchen-checkout/build/third_party/setuptools-0.6c11:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_migrate_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/tempita_0_5:/b/swarming/w/ir/kitchen-checkout/build/third_party/twisted_10_2:/b/swarming/w/ir/kitchen-checkout/build/third_party/uritemplate:/b/swarming/w/ir/kitchen-checkout/build/third_party/site-packages 2019-05-20 17:09:03,459 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmp0Mu0VY' 2019-05-20 17:09:03,459 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmp0Mu0VY' already exists! 2019-05-20 17:09:03,459 - root: [WARNING] task_output_dir existing content: [] 2019-05-20 17:09:03,460 - root: [INFO] collect_cmd: swarming collect -server https://chromium-swarm.appspot.com -worker 50 -task-summary-python -task-output-stdout all -verbose -requests-json /b/swarming/w/ir/tmp/t/tmprgTIU3.json -output-dir /b/swarming/w/ir/tmp/t/tmp0Mu0VY -task-summary-json /b/swarming/w/ir/tmp/t/tmp6OECNJ.json [D2019-05-20T17:09:03.470297-07:00 973 0 auth.go:1265] Minting a new token {"key":"luci_ctx/e0476968ece64082b18c90f514083d020323ffdd2dd5afeca56bf161db888b00", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-05-20T17:09:03.470366-07:00 973 0 luci_ctx.go:138] POST http://127.0.0.1:37093/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/e0476968ece64082b18c90f514083d020323ffdd2dd5afeca56bf161db888b00", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-05-20T17:09:03.472396-07:00 973 0 auth.go:1222] Token expires in 25m30.527658287s {"key":"luci_ctx/e0476968ece64082b18c90f514083d020323ffdd2dd5afeca56bf161db888b00", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 44f07e0fbc6b7f10: exit 0 /b/swarming/swarming_bot.1.zip/third_party/requests/__init__.py:83: RequestsDependencyWarning: Old version of cryptography ([1, 2, 3]) may cause slowdown. Additional test environment: CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox CHROME_HEADLESS=1 LANG=en_US.UTF-8 Command: /b/swarming/w/ir/.swarming_module_cache/vpython/a01b17/bin/python ../../build/android/test_wrapper/logdog_wrapper.py --target cacheinvalidation_unittests --logdog-bin-cmd ../../bin/logdog_butler --store-tombstones --test-launcher-summary-output=/b/swarming/w/iosm1bR5/output.json --gs-results-bucket=chromium-result-details --recover-devices I 0.000s Main command: bin/../../../build/android/test_runner.py gtest --output-directory bin/../. --runtime-deps-path bin/../gen.runtime/third_party/cacheinvalidation/cacheinvalidation_unittests__test_runner_script.runtime_deps --suite cacheinvalidation_unittests -v --store-tombstones --test-launcher-summary-output=/b/swarming/w/iosm1bR5/output.json --gs-results-bucket=chromium-result-details --recover-devices I 0.007s Main condition '<lambda>' met I 0.008s Main condition '<lambda>' met I 3.141s TimeoutThread-1-for-prepare_device(08eb4b8400cac10a) condition 'sd_card_ready' met (0.0s) I 3.680s TimeoutThread-1-for-prepare_device(08eb4b8400cac10a) condition 'pm_ready' met (0.6s) I 3.690s TimeoutThread-1-for-prepare_device(08eb4b8400cac10a) condition 'boot_completed' met (0.6s) I 7.056s calculate_device_checksums condition '<lambda>' met (0.1s) I 8.427s list_tests(08eb4b8400cac10a) flags: I 8.427s list_tests(08eb4b8400cac10a) --gtest_list_tests I 9.826s list_tests(08eb4b8400cac10a) /storage/emulated/legacy/temp_file-ec433e1a7ec98.gtest_out size on device: 682 I 9.893s Main Using external sharding settings. This is shard 0/1 I 9.893s Main STARTING TRY #1/3 I 9.894s Main Will run 28 tests on 1 devices: 08eb4b8400cac10a W 9.917s run_tests_on_device(08eb4b8400cac10a) No tombstones to clear. I 12.025s run_tests_on_device(08eb4b8400cac10a) flags: I 12.025s run_tests_on_device(08eb4b8400cac10a) Getting logdog client. I 13.458s run_tests_on_device(08eb4b8400cac10a) /storage/emulated/legacy/temp_file-fd7be5ddf3d7.gtest_out size on device: 95726 I 13.625s run_tests_on_device(08eb4b8400cac10a) Logcat saved to https://luci-logdog.appspot.com/v/?s=chromium%2Fandroid%2Fswarming%2Flogcats%2F44ef73aaa9198e11%2F%2B%2Flogcat_logcat_-2631999291401687399_20190520T190534-UTC_08eb4b8400cac10a I 13.626s archive Writing text to logdog stream, logcat_logcat_-2631999291401687399_20190520T190534-UTC_08eb4b8400cac10a I 14.228s run_tests_on_device(08eb4b8400cac10a) >>ScopedMainEntryLogger I 14.228s run_tests_on_device(08eb4b8400cac10a) Note: Google Test filter = InvalidationClientImplTest.GenerateNonce:InvalidationClientImplTest.Heartbeats:InvalidationClientImplTest.IncomingAuthErrorMessage:InvalidationClientImplTest.IncomingErrorMessage:InvalidationClientImplTest.Invalidations:InvalidationClientImplTest.NetworkTimeouts:InvalidationClientImplTest.NoRegistrationSummary:InvalidationClientImplTest.Register:InvalidationClientImplTest.ServerRequests:InvalidationClientImplTest.Start:ProtocolHandlerTest.ConfigMessage:ProtocolHandlerTest.ErrorMessage:ProtocolHandlerTest.IncomingCompositeMessage:ProtocolHandlerTest.InvalidInboundMessage:ProtocolHandlerTest.InvalidOutboundMessage:ProtocolHandlerTest.MajorVersionMismatch:ProtocolHandlerTest.MinorVersionMismatch:ProtocolHandlerTest.ReceiveTokenControlOnly:ProtocolHandlerTest.SendInitializeOnly:ProtocolHandlerTest.SendMultipleMessageTypes:ProtocolHandlerTest.TokenMismatch:ProtocolHandlerTest.TokenMissing:ProtocolHandlerTest.UnparseableInboundMessage:RecurringTaskTest.ExponentialBackoffTask:RecurringTaskTest.OneShotTask:RecurringTaskTest.PeriodicTask:ThrottleTest.ThrottlingScripted:ThrottleTest.ThrottlingStorm I 14.228s run_tests_on_device(08eb4b8400cac10a) [==========] Running 28 tests from 4 test suites. I 14.228s run_tests_on_device(08eb4b8400cac10a) [----------] Global test environment set-up. I 14.228s run_tests_on_device(08eb4b8400cac10a) [----------] 10 tests from InvalidationClientImplTest I 14.228s run_tests_on_device(08eb4b8400cac10a) [ RUN ] InvalidationClientImplTest.Start I 14.228s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xc926000 with delay 181 I 14.228s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.228s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097395768) Enqueuing 0xc926000 with delay 181 I 14.228s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1971957912) Running task 0xc926000 I 14.228s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1971957912) Running task 0xc926000 I 14.228s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.228s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1970944627) Enqueuing 0xc926000 with delay 181 I 14.228s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1971957912) Running task 0xc926000 I 14.228s run_tests_on_device(08eb4b8400cac10a) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.228s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.228s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1971957912) Running task 0xc926000 I 14.228s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1971996416 with a delay 1074809869, Now = 0 I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1971957912) Running task 0xc926000 I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "3766161735507495444" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1971996804 with a delay -1097396584, Now = 500000 I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1971996416 with a delay -2147483632, Now = 60000000 I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1971957912) Running task 0xc9a0120 I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "3766161735507495444" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1900400216) Enqueuing 0xc9a0120 with delay 181 I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "3766161735507495444" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "3766161735507495444" I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1971996732 with a delay -1097396640, Now = 1200000000 I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.229s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1971996704 with a delay -1097396640, Now = 0 I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097397248) Enqueuing 0xc9a0120 with delay 181 I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1971996704 with a delay 0, Now = 10000000 I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.230s run_tests_on_device(08eb4b8400cac10a) [ OK ] InvalidationClientImplTest.Start (9 ms) I 14.230s run_tests_on_device(08eb4b8400cac10a) [ RUN ] InvalidationClientImplTest.GenerateNonce I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -2136995840) Enqueuing 0xc926000 with delay 181 I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.230s run_tests_on_device(08eb4b8400cac10a) [ OK ] InvalidationClientImplTest.GenerateNonce (1 ms) I 14.230s run_tests_on_device(08eb4b8400cac10a) [ RUN ] InvalidationClientImplTest.Register I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -2136979456) Enqueuing 0xc926000 with delay 181 I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074809849) Enqueuing 0xc926000 with delay 181 I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1970944627) Enqueuing 0xc926000 with delay 181 I 14.230s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.231s run_tests_on_device(08eb4b8400cac10a) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1972005736 with a delay 1074809869, Now = 0 I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-6957032211966548052" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1972006044 with a delay -1097396848, Now = 500000 I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1972005736 with a delay -2147483632, Now = 60000000 I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc9a0120 I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "-6957032211966548052" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1972011416) Enqueuing 0xc9a0120 with delay 181 I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-6957032211966548052" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-6957032211966548052" I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1972005972 with a delay -1097396904, Now = 1200000000 I 14.231s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1972005944 with a delay -1097396904, Now = 0 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097397512) Enqueuing 0xc9a0120 with delay 181 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1972005944 with a delay 0, Now = 10000000 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9ac470 with delay 181 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc9ac470 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 1972006044 with a delay 1032960, Now = 500000 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9ac470 with delay 181 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 1972005904 with a delay 3, Now = 60000000 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9ac470 with delay 181 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xca26590 I 14.232s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 3 registration_digest: "\244\342\232\241\023\203)\232\315\007\207g\234h\270,V\242\317\221" } client_time_ms: 777601050 max_known_server_time_ms: 314159265 message_id: "2" } registration_message: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } } } I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1963154304) Enqueuing 0xca26590 with delay 181 I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xca26590 I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } registration_status_message: { registration_status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } } } I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 14.233s run_tests_on_device(08eb4b8400cac10a) [ OK ] InvalidationClientImplTest.Register (13 ms) I 14.233s run_tests_on_device(08eb4b8400cac10a) [ RUN ] InvalidationClientImplTest.Invalidations I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 16384) Enqueuing 0xc926000 with delay 181 I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074809849) Enqueuing 0xc926000 with delay 181 I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1970944627) Enqueuing 0xc926000 with delay 181 I 14.233s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.233s run_tests_on_device(08eb4b8400cac10a) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1908995200 with a delay 1074809869, Now = 0 I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "5071636716672306060" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1908995292 with a delay -1097396880, Now = 500000 I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1908995200 with a delay -2147483632, Now = 60000000 I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc9a0120 I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "5071636716672306060" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1971998912) Enqueuing 0xc9a0120 with delay 181 I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "5071636716672306060" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "5071636716672306060" I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.234s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1963096452 with a delay -1097396936, Now = 1200000000 I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1963096424 with a delay -1097396936, Now = 0 I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097397544) Enqueuing 0xc9a0120 with delay 181 I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1963096424 with a delay 0, Now = 10000000 I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1971337057) Enqueuing 0xc9ac470 with delay 181 I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470 I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } invalidation_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true payload: "this is a payload" } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } } } I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true payload: "this is a payload" } I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 632320) Enqueuing 0xc9b87c0 with delay 181 I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 632320) Enqueuing 0xc9b87c0 with delay 181 I 14.235s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 632320) Enqueuing 0xc9b87c0 with delay 181 I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc9b87c0 I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Send-ack] Scheduling 1908995292 with a delay 0, Now = 500000 I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9b87c0 with delay 181 I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc9b87c0 I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc9b87c0 I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xca328e0 I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777601100 max_known_server_time_ms: 314159265 message_id: "2" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } } } I 14.236s run_tests_on_device(08eb4b8400cac10a) [ OK ] InvalidationClientImplTest.Invalidations (12 ms) I 14.236s run_tests_on_device(08eb4b8400cac10a) [ RUN ] InvalidationClientImplTest.ServerRequests I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -2136995712) Enqueuing 0xc926000 with delay 181 I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1971294505) Enqueuing 0xc926000 with delay 181 I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1970944627) Enqueuing 0xc926000 with delay 181 I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.236s run_tests_on_device(08eb4b8400cac10a) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.236s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1972006024 with a delay 1074809869, Now = 0 I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "5885337015007835279" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1972006332 with a delay -1097396736, Now = 500000 I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1972006024 with a delay -2147483632, Now = 60000000 I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc9a0120 I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "5885337015007835279" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1972010296) Enqueuing 0xc9a0120 with delay 181 I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "5885337015007835279" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "5885337015007835279" I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1972006260 with a delay -1097396792, Now = 1200000000 I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.237s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1972006232 with a delay -1097396792, Now = 0 I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097397400) Enqueuing 0xc9a0120 with delay 181 I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1972006232 with a delay 0, Now = 10000000 I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xc9ac470 with delay 181 I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470 I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } registration_sync_request_message: { } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(294)] Adding subtree: { } I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 1972006332 with a delay -1097396760, Now = 500000 I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9ac470 with delay 181 I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(264)] Batching info message for client: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "InvClientTest" } performance_counter: { name: "SentMessageType.INITIALIZE" value: 1 } performance_counter: { name: "SentMessageType.TOTAL" value: 1 } performance_counter: { name: "ReceivedMessageType.INFO_REQUEST" value: 1 } performance_counter: { name: "ReceivedMessageType.REGISTRATION_SYNC_REQUEST" value: 1 } performance_counter: { name: "ReceivedMessageType.TOKEN_CONTROL" value: 1 } performance_counter: { name: "ReceivedMessageType.TOTAL" value: 2 } performance_counter: { name: "ListenerEventType.REISSUE_REGISTRATIONS" value: 1 } performance_counter: { name: "ClientErrorType.PERSISTENT_READ_FAILURE" value: 1 } server_registration_summary_requested: false } I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xca26590 I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.238s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777601050 max_known_server_time_ms: 314159265 message_id: "2" } registration_sync_message: { subtree: { } } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "InvClientTest" } performance_counter: { name: "SentMessageType.INITIALIZE" value: 1 } performance_counter: { name: "SentMessageType.TOTAL" value: 1 } performance_counter: { name: "ReceivedMessageType.INFO_REQUEST" value: 1 } performance_counter: { name: "ReceivedMessageType.REGISTRATION_SYNC_REQUEST" value: 1 } performance_counter: { name: "ReceivedMessageType.TOKEN_CONTROL" value: 1 } performance_counter: { name: "ReceivedMessageType.TOTAL" value: 2 } performance_counter: { name: "ListenerEventType.REISSUE_REGISTRATIONS" value: 1 } performance_counter: { name: "ClientErrorType.PERSISTENT_READ_FAILURE" value: 1 } server_registration_summary_requested: false } } I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 14.239s run_tests_on_device(08eb4b8400cac10a) [ OK ] InvalidationClientImplTest.ServerRequests (12 ms) I 14.239s run_tests_on_device(08eb4b8400cac10a) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 8404992) Enqueuing 0xc926000 with delay 181 I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074809849) Enqueuing 0xc926000 with delay 181 I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1970944627) Enqueuing 0xc926000 with delay 181 I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.239s run_tests_on_device(08eb4b8400cac10a) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1963096512 with a delay 1074809869, Now = 0 I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-6064102117162042889" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1963096900 with a delay -1097396696, Now = 500000 I 14.239s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1963096512 with a delay -2147483632, Now = 60000000 I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc9a0120 I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "-6064102117162042889" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1971995984) Enqueuing 0xc9a0120 with delay 181 I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-6064102117162042889" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-6064102117162042889" I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1963096828 with a delay -1097396752, Now = 1200000000 I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1963096800 with a delay -1097396752, Now = 0 I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097397360) Enqueuing 0xc9a0120 with delay 181 I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1963096800 with a delay 0, Now = 10000000 I 14.240s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xc9ac470 with delay 181 I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470 I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.241s run_tests_on_device(08eb4b8400cac10a) [ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 14.241s run_tests_on_device(08eb4b8400cac10a) [ OK ] InvalidationClientImplTest.IncomingErrorMessage (10 ms) I 14.241s run_tests_on_device(08eb4b8400cac10a) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -2136995712) Enqueuing 0xc926000 with delay 181 I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074809849) Enqueuing 0xc926000 with delay 181 I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1970944627) Enqueuing 0xc926000 with delay 181 I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.241s run_tests_on_device(08eb4b8400cac10a) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.241s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1971996904 with a delay 1074809869, Now = 0 I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1766465239743758763" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1971997212 with a delay -1097396824, Now = 500000 I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1971996904 with a delay -2147483632, Now = 60000000 I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc9a0120 I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "1766465239743758763" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1963155256) Enqueuing 0xc9a0120 with delay 181 I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1766465239743758763" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1766465239743758763" I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1971997140 with a delay -1097396880, Now = 1200000000 I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.242s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1971997112 with a delay -1097396880, Now = 0 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097397488) Enqueuing 0xc9a0120 with delay 181 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1971997112 with a delay 0, Now = 10000000 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9ac470 with delay 181 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc9ac470 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 1971997212 with a delay 270787635, Now = 500000 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9ac470 with delay 181 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 1971997072 with a delay 1, Now = 60000000 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9ac470 with delay 181 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xca26590 I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 1 registration_digest: "\327\003\047\242\324@\3740-O\354\3229\352\000\231\340\204\224\323" } client_time_ms: 777601050 max_known_server_time_ms: 314159265 message_id: "2" } registration_message: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } } } I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.243s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xca26590 with delay 181 I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xca26590 I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.244s run_tests_on_device(08eb4b8400cac10a) [ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message I 14.244s run_tests_on_device(08eb4b8400cac10a) [WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 14.244s run_tests_on_device(08eb4b8400cac10a) [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (12 ms) I 14.244s run_tests_on_device(08eb4b8400cac10a) [ RUN ] InvalidationClientImplTest.NetworkTimeouts I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 128) Enqueuing 0xc926000 with delay 181 I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1971294505) Enqueuing 0xc926000 with delay 181 I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1970944627) Enqueuing 0xc926000 with delay 181 I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.244s run_tests_on_device(08eb4b8400cac10a) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1908995104 with a delay 1074809869, Now = 0 I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.244s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-4874946632805487317" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1963154060 with a delay -1097396736, Now = 500000 I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1908995104 with a delay -2147483632, Now = 60000000 I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc9a0120 I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "-4874946632805487317" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1971995744) Enqueuing 0xc9a0120 with delay 181 I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-4874946632805487317" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-4874946632805487317" I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1963153988 with a delay -1097396792, Now = 1200000000 I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1972000768 with a delay -1097396792, Now = 0 I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.245s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097397400) Enqueuing 0xc9a0120 with delay 181 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1972000768 with a delay 0, Now = 10000000 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9ac470 with delay 181 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc9ac470 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 1963154060 with a delay 270787635, Now = 500000 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9ac470 with delay 181 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 1908995272 with a delay 1, Now = 60000000 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9ac470 with delay 181 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xca26590 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 1 registration_digest: "\327\003\047\242\324@\3740-O\354\3229\352\000\231\340\204\224\323" } client_time_ms: 777601050 max_known_server_time_ms: 314159265 message_id: "2" } registration_message: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } } } I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xd3297a0 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0x1025e700 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0x102e4b70 I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(99)] Registration state not in sync with server: Last known digest: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }, Requested regs: SimpleRegistrationStore: 1 registrations I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true I 14.246s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(264)] Batching info message for client: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "InvClientTest" } server_registration_summary_requested: true } I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1963154060 with a delay -1097396768, Now = 500000 I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x102e4b70 with delay 181 I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1908995272 with a delay 1970259620, Now = 60000000 I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x102e4b70 with delay 181 I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0x1035ec90 I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 1 registration_digest: "\327\003\047\242\324@\3740-O\354\3229\352\000\231\340\204\224\323" } client_time_ms: 777661050 max_known_server_time_ms: 314159265 message_id: "3" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "InvClientTest" } server_registration_summary_requested: true } } I 14.247s run_tests_on_device(08eb4b8400cac10a) [ OK ] InvalidationClientImplTest.NetworkTimeouts (10 ms) I 14.247s run_tests_on_device(08eb4b8400cac10a) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -2136995712) Enqueuing 0xc926000 with delay 181 I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1971294505) Enqueuing 0xc926000 with delay 181 I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1970944627) Enqueuing 0xc926000 with delay 181 I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.247s run_tests_on_device(08eb4b8400cac10a) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.247s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1971996904 with a delay 1074809869, Now = 0 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc926000 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-165985183253908912" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1971997212 with a delay -1097396744, Now = 500000 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1971996904 with a delay -2147483632, Now = 60000000 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1871267064) Running task 0xc9a0120 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "-165985183253908912" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1972000560) Enqueuing 0xc9a0120 with delay 181 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-165985183253908912" registration_summary: { num_registrations: 1 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-165985183253908912" I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1971997140 with a delay -1097396800, Now = 1200000000 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.248s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1971997112 with a delay -1097396800, Now = 0 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 1 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097397408) Enqueuing 0xc9a0120 with delay 181 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1971997112 with a delay 0, Now = 10000000 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xc9ac470 with delay 181 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9ac470 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" server_time_ms: 314159265 message_id: "message-id-for-test" } } I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xd3297a0 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-impl_test.cc(477)] Reg manager state: { client_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_summary: { num_registrations: 1 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } } I 14.249s run_tests_on_device(08eb4b8400cac10a) [ OK ] InvalidationClientImplTest.NoRegistrationSummary (6 ms) I 14.249s run_tests_on_device(08eb4b8400cac10a) [ RUN ] InvalidationClientImplTest.Heartbeats I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 134217728) Enqueuing 0xc926000 with delay 181 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1971294505) Enqueuing 0xc926000 with delay 181 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.249s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1970944627) Enqueuing 0xc926000 with delay 181 I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.250s run_tests_on_device(08eb4b8400cac10a) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1963096424 with a delay 1074809869, Now = 0 I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc926000 I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "2191632118096243841" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 1963096812 with a delay -1097396704, Now = 500000 I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1963096424 with a delay -2147483632, Now = 60000000 I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1953891728) Running task 0xc9a0120 I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "2191632118096243841" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1971995520) Enqueuing 0xc9a0120 with delay 181 I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.250s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "2191632118096243841" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "2191632118096243841" I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1963096740 with a delay -1097396760, Now = 1200000000 I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1963096712 with a delay -1097396760, Now = 0 I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(836)] Receivced new server registration summary ({ num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" }); will make 0 upcalls I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097397368) Enqueuing 0xc9a0120 with delay 181 I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1963096712 with a delay 0, Now = 10000000 I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc9a0120 with delay 181 I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 181) Running task 0xc9a0120 I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1971995428) Running task 0xd3297a0 I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1971995428) Running task 0x1025e700 I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1971995428) Running task 0x54208d20 I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(264)] Batching info message for client: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "InvClientTest" } performance_counter: { name: "SentMessageType.INITIALIZE" value: 1 } performance_counter: { name: "SentMessageType.TOTAL" value: 1 } performance_counter: { name: "ReceivedMessageType.TOKEN_CONTROL" value: 1 } performance_counter: { name: "ReceivedMessageType.TOTAL" value: 1 } performance_counter: { name: "ListenerEventType.REISSUE_REGISTRATIONS" value: 1 } performance_counter: { name: "ClientErrorType.PERSISTENT_READ_FAILURE" value: 1 } server_registration_summary_requested: false } I 14.251s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1963096812 with a delay -1097396768, Now = 500000 I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x54208d20 with delay 181 I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1963096740 with a delay 12, Now = 1200000000 I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x54208d20 with delay 181 I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1971995428) Running task 0x54282e40 I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 778801000 max_known_server_time_ms: 314159265 message_id: "2" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "InvClientTest" } performance_counter: { name: "SentMessageType.INITIALIZE" value: 1 } performance_counter: { name: "SentMessageType.TOTAL" value: 1 } performance_counter: { name: "ReceivedMessageType.TOKEN_CONTROL" value: 1 } performance_counter: { name: "ReceivedMessageType.TOTAL" value: 1 } performance_counter: { name: "ListenerEventType.REISSUE_REGISTRATIONS" value: 1 } performance_counter: { name: "ClientErrorType.PERSISTENT_READ_FAILURE" value: 1 } server_registration_summary_requested: false } } I 14.252s run_tests_on_device(08eb4b8400cac10a) [ OK ] InvalidationClientImplTest.Heartbeats (14 ms) I 14.252s run_tests_on_device(08eb4b8400cac10a) [----------] 10 tests from InvalidationClientImplTest (100 ms total) I 14.252s run_tests_on_device(08eb4b8400cac10a) I 14.252s run_tests_on_device(08eb4b8400cac10a) [----------] 13 tests from ProtocolHandlerTest I 14.252s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ProtocolHandlerTest.SendInitializeOnly I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074822763) Enqueuing 0xc926000 with delay 181 I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1074809849) Running task 0xc926000 I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(230)] Batching initialize message for client: Startup, { client_type: 2 nonce: "unit-test-nonce" application_client_id: { client_type: 2 client_name: "unit-test-client-id" } digest_serialization_type: BYTE_BASED } I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Startup] Scheduling 1971994532 with a delay -1097396672, Now = 500000 I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1074809849) Running task 0xc9a0120 I 14.252s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "unit-test-nonce" application_client_id: { client_type: 2 client_name: "unit-test-client-id" } digest_serialization_type: BYTE_BASED } } I 14.252s run_tests_on_device(08eb4b8400cac10a) [ OK ] ProtocolHandlerTest.SendInitializeOnly (2 ms) I 14.252s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "fake nonce" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } I 14.253s run_tests_on_device(08eb4b8400cac10a) [ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms) I 14.253s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0xc926000 with delay 181 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1970725289) Enqueuing 0xc926000 with delay 181 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1970725289) Enqueuing 0xc926000 with delay 181 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1908994864) Enqueuing 0xc926000 with delay 181 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1908995000) Enqueuing 0xc926000 with delay 181 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1971999416) Enqueuing 0xc926000 with delay 181 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1074809849) Running task 0xc926000 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(264)] Batching info message for client: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "unit-test" } performance_counter: { name: "x" value: 3 } performance_counter: { name: "y" value: 81 } server_registration_summary_requested: true } I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1963097612 with a delay -1097397104, Now = 500000 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1074809849) Running task 0xc926000 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1074809849) Running task 0xc926000 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1074809849) Running task 0xc926000 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1074809849) Running task 0xc926000 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1074809849) Running task 0xc926000 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1074809849) Running task 0xc9a0120 I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" I 14.253s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } registration_message: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } registration: { object_id: { source: 2 name: "oid1" } op_type: UNREGISTER } registration: { object_id: { source: 2 name: "oid2" } op_type: UNREGISTER } } registration_sync_message: { subtree: { registered_object: { source: 2 name: "oid0" } } } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "unit-test" } performance_counter: { name: "x" value: 3 } performance_counter: { name: "y" value: 81 } server_registration_summary_requested: true } } I 14.254s run_tests_on_device(08eb4b8400cac10a) [ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (3 ms) I 14.254s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage I 14.254s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } invalidation_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } } registration_status_message: { registration_status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } } registration_sync_request_message: { } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } I 14.254s run_tests_on_device(08eb4b8400cac10a) [ OK ] ProtocolHandlerTest.IncomingCompositeMessage (2 ms) I 14.254s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage I 14.254s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } I 14.254s run_tests_on_device(08eb4b8400cac10a) [ERROR:ticl-message-validator.cc(316)] required field protocol_version missing from { client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } I 14.254s run_tests_on_device(08eb4b8400cac10a) [ERROR:ticl-message-validator.cc(361)] field header failed validation in { header: { client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } I 14.254s run_tests_on_device(08eb4b8400cac10a) [ERROR:protocol-handler.cc(145)] Received invalid message: { header: { client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } I 14.254s run_tests_on_device(08eb4b8400cac10a) [ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms) I 14.254s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch I 14.254s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } I 14.254s run_tests_on_device(08eb4b8400cac10a) [ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } I 14.254s run_tests_on_device(08eb4b8400cac10a) [ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms) I 14.254s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch I 14.254s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 4 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } I 14.254s run_tests_on_device(08eb4b8400cac10a) [ OK ] ProtocolHandlerTest.MinorVersionMismatch (2 ms) I 14.254s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ProtocolHandlerTest.ConfigMessage I 14.254s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } I 14.254s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1971996672) Enqueuing 0xc926000 with delay 181 I 14.254s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1970744137) Running task 0xc926000 I 14.254s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(264)] Batching info message for client: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "unit-test" } server_registration_summary_requested: false } I 14.254s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1971994532 with a delay -1097396488, Now = 500000 I 14.254s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.254s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1970744137) Running task 0xc9a0120 I 14.254s run_tests_on_device(08eb4b8400cac10a) [WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 I 14.254s run_tests_on_device(08eb4b8400cac10a) [ OK ] ProtocolHandlerTest.ConfigMessage (11 ms) I 14.255s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ProtocolHandlerTest.ErrorMessage I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } I 14.255s run_tests_on_device(08eb4b8400cac10a) [ OK ] ProtocolHandlerTest.ErrorMessage (1 ms) I 14.255s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ProtocolHandlerTest.TokenMismatch I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } I 14.255s run_tests_on_device(08eb4b8400cac10a) [ OK ] ProtocolHandlerTest.TokenMismatch (1 ms) I 14.255s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ProtocolHandlerTest.TokenMissing I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1971009601) Enqueuing 0xc926000 with delay 181 I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1970744137) Running task 0xc926000 I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(264)] Batching info message for client: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "unit-test" } server_registration_summary_requested: true } I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Send-info] Scheduling 1971994532 with a delay -1097396320, Now = 500000 I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1970744137) Running task 0xc9a0120 I 14.255s run_tests_on_device(08eb4b8400cac10a) [WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } I 14.255s run_tests_on_device(08eb4b8400cac10a) [WARNING:protocol-handler.cc(313)] Unable to build message I 14.255s run_tests_on_device(08eb4b8400cac10a) [ OK ] ProtocolHandlerTest.TokenMissing (2 ms) I 14.255s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1971995848) Enqueuing 0xc926000 with delay 181 I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1970744137) Running task 0xc926000 I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Send-ack] Scheduling 1971994532 with a delay 63, Now = 500000 I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xc926000 with delay 181 I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1970744137) Running task 0xc9a0120 I 14.255s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" I 14.255s run_tests_on_device(08eb4b8400cac10a) [ERROR:ticl-message-validator.cc(198)] required field version missing from { object_id: { source: 2 name: "oid0" } is_known_version: true is_trickle_restart: true } I 14.255s run_tests_on_device(08eb4b8400cac10a) [ERROR:ticl-message-validator.cc(216)] field invalidation #0 failed validation in { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true is_trickle_restart: true } } I 14.255s run_tests_on_device(08eb4b8400cac10a) [ERROR:ticl-message-validator.cc(308)] field invalidation_ack_message failed validation in { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true is_trickle_restart: true } } } I 14.256s run_tests_on_device(08eb4b8400cac10a) [ERROR:protocol-handler.cc(323)] Tried to send invalid message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true is_trickle_restart: true } } } I 14.256s run_tests_on_device(08eb4b8400cac10a) [ OK ] ProtocolHandlerTest.InvalidOutboundMessage (2 ms) I 14.256s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:protocol-handler.cc(139)] Incoming message: { } I 14.256s run_tests_on_device(08eb4b8400cac10a) [ERROR:ticl-message-validator.cc(361)] required field header missing from { } I 14.256s run_tests_on_device(08eb4b8400cac10a) [ERROR:protocol-handler.cc(145)] Received invalid message: { } I 14.256s run_tests_on_device(08eb4b8400cac10a) [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) I 14.256s run_tests_on_device(08eb4b8400cac10a) [----------] 13 tests from ProtocolHandlerTest (31 ms total) I 14.256s run_tests_on_device(08eb4b8400cac10a) I 14.256s run_tests_on_device(08eb4b8400cac10a) [----------] 3 tests from RecurringTaskTest I 14.256s run_tests_on_device(08eb4b8400cac10a) [ RUN ] RecurringTaskTest.PeriodicTask I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 1971992472 with a delay 10, Now = 10000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x0 with delay 0 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900400216) Running task 0x2710 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992496) Task running: 10000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1971992472 with a delay 1971841284, Now = 60000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x2710 with delay 0 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900400216) Running task 0x11170 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992512) Task running: 70000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1971992472 with a delay 1971841284, Now = 60000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x11170 with delay 0 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900400216) Running task 0x1fbd0 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992496) Task running: 130000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1971992472 with a delay 1971841284, Now = 60000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x1fbd0 with delay 0 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900400216) Running task 0x2e630 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992512) Task running: 190000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1971992472 with a delay 1971841284, Now = 60000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x2e630 with delay 0 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900400216) Running task 0x3d090 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992496) Task running: 250000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1971992472 with a delay 1971841284, Now = 60000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x3d090 with delay 0 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900400216) Running task 0x4baf0 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992512) Task running: 310000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1971992472 with a delay 1971841284, Now = 60000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x4baf0 with delay 0 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900400216) Running task 0x5a550 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992496) Task running: 370000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1971992472 with a delay 1971841284, Now = 60000 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x5a550 with delay 0 I 14.256s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900400216) Running task 0x68fb0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992512) Task running: 430000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [ OK ] RecurringTaskTest.PeriodicTask (4 ms) I 14.257s run_tests_on_device(08eb4b8400cac10a) [ RUN ] RecurringTaskTest.ExponentialBackoffTask I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 1871268016 with a delay 0, Now = 10000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x0 with delay 0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900441184) Running task 0x2710 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992456) Task running: 10000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1871268016 with a delay 1971841284, Now = 50000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x2710 with delay 0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900441184) Running task 0xea60 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992472) Task running: 60000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1871268016 with a delay 1971841284, Now = 149000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xea60 with delay 0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900441184) Running task 0x33450 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992456) Task running: 210000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1871268016 with a delay 1971841284, Now = 248000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x33450 with delay 0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900441184) Running task 0x704e0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992472) Task running: 460000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1871268016 with a delay 1971841284, Now = 446000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x704e0 with delay 0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900441184) Running task 0xde2b0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992456) Task running: 910000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1871268016 with a delay 1971841284, Now = 842000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xde2b0 with delay 0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900441184) Running task 0x1adb00 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992472) Task running: 1760000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1871268016 with a delay 1971841284, Now = 1040000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x1adb00 with delay 0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900441184) Running task 0x2ab980 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992456) Task running: 2800000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [Retry] Scheduling 1871268016 with a delay 1971841284, Now = 1040000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x2ab980 with delay 0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900441184) Running task 0x3a9800 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992472) Task running: 3840000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [ OK ] RecurringTaskTest.ExponentialBackoffTask (4 ms) I 14.257s run_tests_on_device(08eb4b8400cac10a) [ RUN ] RecurringTaskTest.OneShotTask I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 1971992472 with a delay 0, Now = 10000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x0 with delay 0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1971992520) Running task 0x2710 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992496) Task running: 10000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 1971992472 with a delay 0, Now = 10000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x2710 with delay 0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 1900400216) Running task 0x4e20 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:recurring-task_test.cc(71)] (1971992496) Task running: 20000 I 14.257s run_tests_on_device(08eb4b8400cac10a) [ OK ] RecurringTaskTest.OneShotTask (2 ms) I 14.257s run_tests_on_device(08eb4b8400cac10a) [----------] 3 tests from RecurringTaskTest (10 ms total) I 14.257s run_tests_on_device(08eb4b8400cac10a) I 14.257s run_tests_on_device(08eb4b8400cac10a) [----------] 2 tests from ThrottleTest I 14.257s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ThrottleTest.ThrottlingScripted I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x13880 with delay 0 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xf4240 I 14.257s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xe4e1c0 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3938700 I 14.258s run_tests_on_device(08eb4b8400cac10a) [ OK ] ThrottleTest.ThrottlingScripted (2 ms) I 14.258s run_tests_on_device(08eb4b8400cac10a) [ RUN ] ThrottleTest.ThrottlingStorm I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x2710 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xf4240 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xf4240 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x1e8480 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x1e8480 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x2dc6c0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x2dc6c0 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3d0900 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x3d0900 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x4c4b40 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x4c4b40 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x5b8d80 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097396008) Enqueuing 0x5b8d80 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3938700 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x3938700 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3a2c940 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x3a2c940 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3b20b80 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x3b20b80 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3c14dc0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x3c14dc0 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3d09000 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x3d09000 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3dfd240 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x3dfd240 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x3ef1480 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097396008) Enqueuing 0x3ef1480 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7270e00 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x7270e00 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7365040 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x7365040 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7459280 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x7459280 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x754d4c0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x754d4c0 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7641700 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x7641700 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7735940 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0x7735940 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x7829b80 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097396008) Enqueuing 0x7829b80 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xaba9500 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xaba9500 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xac9d740 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xac9d740 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xad91980 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xad91980 with delay 0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xae85bc0 I 14.258s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xae85bc0 with delay 0 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xaf79e00 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xaf79e00 with delay 0 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xb06e040 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xb06e040 with delay 0 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xb162280 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097396008) Enqueuing 0xb162280 with delay 0 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe4e1c00 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xe4e1c00 with delay 0 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe5d5e40 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xe5d5e40 with delay 0 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe6ca080 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xe6ca080 with delay 0 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe7be2c0 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xe7be2c0 with delay 0 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe8b2500 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xe8b2500 with delay 0 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xe9a6740 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: 1074823767) Enqueuing 0xe9a6740 with delay 0 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0xea9a980 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(33)] (Now: -1097396008) Enqueuing 0xea9a980 with delay 0 I 14.259s run_tests_on_device(08eb4b8400cac10a) [INFO:deterministic-scheduler.cc(75)] (Now: 0) Running task 0x11e1a300 I 14.259s run_tests_on_device(08eb4b8400cac10a) [ OK ] ThrottleTest.ThrottlingStorm (9 ms) I 14.259s run_tests_on_device(08eb4b8400cac10a) [----------] 2 tests from ThrottleTest (11 ms total) I 14.259s run_tests_on_device(08eb4b8400cac10a) I 14.259s run_tests_on_device(08eb4b8400cac10a) [----------] Global test environment tear-down I 14.259s run_tests_on_device(08eb4b8400cac10a) [==========] 28 tests from 4 test suites ran. (153 ms total) I 14.259s run_tests_on_device(08eb4b8400cac10a) [ PASSED ] 28 tests. I 14.259s run_tests_on_device(08eb4b8400cac10a) <<ScopedMainEntryLogger I 14.261s run_tests_on_device(08eb4b8400cac10a) Finished running tests on this device. I 14.264s Main FINISHED TRY #1/3 I 14.264s Main All tests completed. C 14.264s Main ******************************************************************************** C 14.264s Main Summary C 14.264s Main ******************************************************************************** C 14.264s Main [==========] 28 tests ran. C 14.264s Main [ PASSED ] 28 tests. C 14.264s Main ******************************************************************************** I 14.265s tear_down_device(08eb4b8400cac10a) Wrote device cache: /b/swarming/w/ir/out/Release/device_cache_08eb4b8400cac10a.json I 14.267s Main Generated json results file at /b/swarming/w/itgtSCDs/tmpDdpJWa I 14.267s Main Finishing archiving output. [W2019-05-20T19:05:37.217909Z 337 0 butler.go:240] Butler Context was cancelled. Initiating shutdown. {"error":"context canceled"} INFO:devil.utils.timeout_retry:condition 'logdog_stopped' not met [E2019-05-20T19:05:37.281809Z 337 0 main.go:205] Butler terminated with error. {"error":"context canceled"} [E2019-05-20T19:05:37.281867Z 337 0 main.go:233] Failed to serve. original error: context canceled [I2019-05-20T19:05:37.282004Z 337 0 main.go:349] Terminating. {"returnCode":250} INFO:devil.utils.timeout_retry:condition 'logdog_stopped' met 2019-05-20 17:09:04,382 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmp0Mu0VY/44f07e0fbc6b7f10'] 2019-05-20 17:09:04,383 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmp0Mu0VY/44f07e0fbc6b7f10/output.json'] 2019-05-20 17:09:04,383 - root: [INFO] merge_cmd: /b/swarming/w/ir/cache/vpython/ba947a/bin/python /b/swarming/w/ir/cache/builder/src/build/android/pylib/results/presentation/test_results_presentation.py --build-properties {"blamelist": ["jbudorick@chromium.org"], "bot_id": "swarm1781-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:5071639625-1lppvbtck1morgivc6sq4dul7klu27sd@developer.gserviceaccount.com", "created_ts": 1558394515252356, "id": "8912898628733151808", "project": "chromium", "tags": ["build_address:luci.chromium.try/android-kitkat-arm-rel/266104", "builder:android-kitkat-arm-rel", "buildset:patch/gerrit/chromium-review.googlesource.com/1607679/2", "cq_experimental:false", "user_agent:cq"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "android-kitkat-arm-rel", "buildnumber": 266104, "category": "cq", "got_angle_revision": "08146a27b7bc07d6a2426591de7f1ec1a06bed42", "got_dawn_revision": "2bc3169f0d64a07469b73c318a2e4c887f8eb17a", "got_nacl_revision": "ca374f5112fca6b36fc5d73e117a60b82f394993", "got_revision": "f815e39bad34c1806419c6aaaf5230b5d5776c2e", "got_revision_cp": "refs/heads/master@{#661526}", "got_swarming_client_revision": "1b65f4e862045f3ba430a4cbd0643f5b1b66c230", "got_v8_revision": "7afc9ca45927216f43bc869135b33134af3a64de", "got_v8_revision_cp": "refs/heads/7.6.224@{#1}", "got_webrtc_revision": "1ff16c87aa63d4f9b63a238fc0664b5e625e9884", "got_webrtc_revision_cp": "refs/heads/master@{#27992}", "mastername": "tryserver.chromium.android", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1607679, "patch_project": "chromium/src", "patch_ref": "refs/changes/79/1607679/2", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 2, "patch_storage": "gerrit", "path_config": "generic", "reason": "CQ", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src", "revision": "HEAD"} --summary-json /b/swarming/w/ir/tmp/t/tmp6OECNJ.json --task-output-dir /b/swarming/w/ir/tmp/t/tmp0Mu0VY --bucket chromium-result-details --test-name cacheinvalidation_unittests -o /b/swarming/w/ir/tmp/t/tmpc4OiWt.json /b/swarming/w/ir/tmp/t/tmp0Mu0VY/44f07e0fbc6b7f10/output.json Running ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/build/android/pylib/results/presentation/test_results_presentation.py', '--build-properties', '{"blamelist": ["jbudorick@chromium.org"], "bot_id": "swarm1781-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:5071639625-1lppvbtck1morgivc6sq4dul7klu27sd@developer.gserviceaccount.com", "created_ts": 1558394515252356, "id": "8912898628733151808", "project": "chromium", "tags": ["build_address:luci.chromium.try/android-kitkat-arm-rel/266104", "builder:android-kitkat-arm-rel", "buildset:patch/gerrit/chromium-review.googlesource.com/1607679/2", "cq_experimental:false", "user_agent:cq"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "android-kitkat-arm-rel", "buildnumber": 266104, "category": "cq", "got_angle_revision": "08146a27b7bc07d6a2426591de7f1ec1a06bed42", "got_dawn_revision": "2bc3169f0d64a07469b73c318a2e4c887f8eb17a", "got_nacl_revision": "ca374f5112fca6b36fc5d73e117a60b82f394993", "got_revision": "f815e39bad34c1806419c6aaaf5230b5d5776c2e", "got_revision_cp": "refs/heads/master@{#661526}", "got_swarming_client_revision": "1b65f4e862045f3ba430a4cbd0643f5b1b66c230", "got_v8_revision": "7afc9ca45927216f43bc869135b33134af3a64de", "got_v8_revision_cp": "refs/heads/7.6.224@{#1}", "got_webrtc_revision": "1ff16c87aa63d4f9b63a238fc0664b5e625e9884", "got_webrtc_revision_cp": "refs/heads/master@{#27992}", "mastername": "tryserver.chromium.android", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1607679, "patch_project": "chromium/src", "patch_ref": "refs/changes/79/1607679/2", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 2, "patch_storage": "gerrit", "path_config": "generic", "reason": "CQ", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src", "revision": "HEAD"}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp6OECNJ.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmp0Mu0VY', u'--bucket', u'chromium-result-details', u'--test-name', u'cacheinvalidation_unittests', '-o', '/b/swarming/w/ir/tmp/t/tmpc4OiWt.json', '/b/swarming/w/ir/tmp/t/tmp0Mu0VY/44f07e0fbc6b7f10/output.json'] in None (env: None) Command ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/build/android/pylib/results/presentation/test_results_presentation.py', '--build-properties', '{"blamelist": ["jbudorick@chromium.org"], "bot_id": "swarm1781-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:5071639625-1lppvbtck1morgivc6sq4dul7klu27sd@developer.gserviceaccount.com", "created_ts": 1558394515252356, "id": "8912898628733151808", "project": "chromium", "tags": ["build_address:luci.chromium.try/android-kitkat-arm-rel/266104", "builder:android-kitkat-arm-rel", "buildset:patch/gerrit/chromium-review.googlesource.com/1607679/2", "cq_experimental:false", "user_agent:cq"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "android-kitkat-arm-rel", "buildnumber": 266104, "category": "cq", "got_angle_revision": "08146a27b7bc07d6a2426591de7f1ec1a06bed42", "got_dawn_revision": "2bc3169f0d64a07469b73c318a2e4c887f8eb17a", "got_nacl_revision": "ca374f5112fca6b36fc5d73e117a60b82f394993", "got_revision": "f815e39bad34c1806419c6aaaf5230b5d5776c2e", "got_revision_cp": "refs/heads/master@{#661526}", "got_swarming_client_revision": "1b65f4e862045f3ba430a4cbd0643f5b1b66c230", "got_v8_revision": "7afc9ca45927216f43bc869135b33134af3a64de", "got_v8_revision_cp": "refs/heads/7.6.224@{#1}", "got_webrtc_revision": "1ff16c87aa63d4f9b63a238fc0664b5e625e9884", "got_webrtc_revision_cp": "refs/heads/master@{#27992}", "mastername": "tryserver.chromium.android", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1607679, "patch_project": "chromium/src", "patch_ref": "refs/changes/79/1607679/2", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 2, "patch_storage": "gerrit", "path_config": "generic", "reason": "CQ", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src", "revision": "HEAD"}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp6OECNJ.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmp0Mu0VY', u'--bucket', u'chromium-result-details', u'--test-name', u'cacheinvalidation_unittests', '-o', '/b/swarming/w/ir/tmp/t/tmpc4OiWt.json', '/b/swarming/w/ir/tmp/t/tmp0Mu0VY/44f07e0fbc6b7f10/output.json'] returned exit code 0