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

python -u /b/swarming/w/ir/kitchen-checkout/build/scripts/tools/runit.py --show-path --with-third-party-lib -- python /b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/collect_task.py --verbose -o /b/swarming/w/ir/tmp/t/tmpz9l8kr.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpsX9YTQ --merge-script /b/swarming/w/ir/cache/builder/src/build/android/pylib/results/presentation/test_results_presentation.py --merge-script-stdout-file /b/swarming/w/ir/tmp/t/tmp0QMfrHmerge_script_log --merge-additional-args '["--bucket", "chromium-result-details", "--test-name", "cacheinvalidation_unittests"]' --build-properties '{"bot_id": "swarm1596-c4", "branch": "refs/heads/master", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552978929671795, "id": "8918577281799034752", "project": "chromium", "tags": ["build_address:luci.chromium.ci/android-marshmallow-arm64-rel/13567", "builder:android-marshmallow-arm64-rel", "buildset:commit/git/ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "gitiles_ref:refs/heads/master", "scheduler_invocation_id:9084007344139014192", "scheduler_job_id:chromium/android-marshmallow-arm64-rel", "user_agent:luci-scheduler"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "android-marshmallow-arm64-rel", "buildnumber": 13567, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "got_revision_cp": "refs/heads/master@{#641821}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "repository": "https://chromium.googlesource.com/chromium/src.git", "revision": "ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc"}' --summary-json-file /b/swarming/w/ir/tmp/t/tmpO1j5Vj.json -- 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/tmpCct2Ab.json in dir /b/swarming/w/ir/k: allow_subannotations: True cmd: ['python', '-u', '/b/swarming/w/ir/kitchen-checkout/build/scripts/tools/runit.py', '--show-path', '--with-third-party-lib', '--', 'python', '/b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/collect_task.py', '--verbose', '-o', '/b/swarming/w/ir/tmp/t/tmpz9l8kr.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpsX9YTQ', '--merge-script', '/b/swarming/w/ir/cache/builder/src/build/android/pylib/results/presentation/test_results_presentation.py', '--merge-script-stdout-file', '/b/swarming/w/ir/tmp/t/tmp0QMfrHmerge_script_log', '--merge-additional-args', '["--bucket", "chromium-result-details", "--test-name", "cacheinvalidation_unittests"]', '--build-properties', '{"bot_id": "swarm1596-c4", "branch": "refs/heads/master", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552978929671795, "id": "8918577281799034752", "project": "chromium", "tags": ["build_address:luci.chromium.ci/android-marshmallow-arm64-rel/13567", "builder:android-marshmallow-arm64-rel", "buildset:commit/git/ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "gitiles_ref:refs/heads/master", "scheduler_invocation_id:9084007344139014192", "scheduler_job_id:chromium/android-marshmallow-arm64-rel", "user_agent:luci-scheduler"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "android-marshmallow-arm64-rel", "buildnumber": 13567, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "got_revision_cp": "refs/heads/master@{#641821}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "repository": "https://chromium.googlesource.com/chromium/src.git", "revision": "ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc"}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmpO1j5Vj.json', '--', '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/tmpCct2Ab.json'] env: {'CHROME_HEADLESS': '1', 'PATH': '/b/swarming/w/ir/cache/builder/src/third_party/android_tools/sdk/platform-tools:/b/swarming/w/ir/cache/builder/src/build/android:%(PATH)s'} env_prefixes: {'PATH': '/b/swarming/w/ir/cache/swarming_client'} env_suffixes: {} infra_step: False name_tokens: ('cacheinvalidation_unittests on Android device Nexus 5X',) ok_ret: frozenset([0]) step_test_data: <lambda>(...) trigger_specs: () full environment: ADDRFAM: inet BOTO_CONFIG: /b/swarming/w/ir/tmp/gsutil_task/.boto BUILDBUCKET_EXPERIMENTAL: FALSE CHROME_HEADLESS: 1 CIPD_CACHE_DIR: /b/swarming/cipd_cache/cache CIPD_PROTOCOL: v2 DEVSHELL_CLIENT_PORT: 41935 DOCKER_CONFIG: /b/swarming/w/ir/tmp/docker_cfg_task DOCKER_TMPDIR: /b/swarming/w/ir/tmp/docker_tmp_task GIT_CONFIG_NOSYSTEM: 1 GIT_TERMINAL_PROMPT: 0 HOME: /home/chrome-bot IFACE: eth0 INFRA_GIT_WRAPPER_HOME: /b/swarming/w/ir/tmp/git_home_task LOGDOG_COORDINATOR_HOST: logs.chromium.org LOGDOG_STREAM_PREFIX: buildbucket/cr-buildbucket.appspot.com/8918577281799034752 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/itcmoGDa/luci_context.834189310 MAC_CHROMIUM_TMPDIR: /b/swarming/w/ir/tmp/t METHOD: dhcp NO_GCE_CHECK: False PATH: /b/swarming/w/ir/cache/swarming_client:/b/swarming/w/ir/cache/builder/src/third_party/android_tools/sdk/platform-tools:/b/swarming/w/ir/cache/builder/src/build/android:/b/swarming/w/ir/cipd_bin_packages:/b/swarming/w/ir/cipd_bin_packages/bin:/b/swarming/cipd_cache/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin PWD: /b/swarming/w/ir/k PYTHONIOENCODING: UTF-8 PYTHONUNBUFFERED: 1 ROOT_SETUP_LOG: /var/log/messages/chromebuild/root-setup.log SHLVL: 1 STARTUP_LOG: /var/log/messages/chromebuild/startup.log SWARMING_BOT_ID: swarm1596-c4 SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 43ad9371aeb44611 TEMP: /b/swarming/w/ir/tmp/t TEMPDIR: /b/swarming/w/ir/tmp/t TERM: linux TMP: /b/swarming/w/ir/tmp/t TMPDIR: /b/swarming/w/ir/tmp/t UPSTART_EVENTS: net-device-up UPSTART_INSTANCE: UPSTART_JOB: chromebuild-startup USER: chrome-bot USERNAME: chrome-bot VPYTHON_VIRTUALENV_ROOT: /b/swarming/w/ir/cache/vpython _: /b/swarming/w/ir/cipd_bin_packages/vpython 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-03-19 00:40:17,049 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmpsX9YTQ' 2019-03-19 00:40:17,049 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmpsX9YTQ' already exists! 2019-03-19 00:40:17,049 - root: [WARNING] task_output_dir existing content: [] 2019-03-19 00:40:17,049 - 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/tmpCct2Ab.json -output-dir /b/swarming/w/ir/tmp/t/tmpsX9YTQ -task-summary-json /b/swarming/w/ir/tmp/t/tmpO1j5Vj.json [D2019-03-19T00:40:17.056795-07:00 9454 0 auth.go:1265] Minting a new token {"key":"luci_ctx/5fba2823bba018c5c2e1dfbcf03f287fe3d5a0d0479965524f652016b8212c6f", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-19T00:40:17.056873-07:00 9454 0 luci_ctx.go:138] POST http://127.0.0.1:34282/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/5fba2823bba018c5c2e1dfbcf03f287fe3d5a0d0479965524f652016b8212c6f", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-19T00:40:17.058774-07:00 9454 0 auth.go:1222] Token expires in 5m39.941278912s {"key":"luci_ctx/5fba2823bba018c5c2e1dfbcf03f287fe3d5a0d0479965524f652016b8212c6f", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 43adb1265962dd10: exit 0 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/9ede37/bin/python ../../build/android/test_wrapper/logdog_wrapper.py --target cacheinvalidation_unittests --logdog-bin-cmd ../../bin/logdog_butler --store-tombstones --gs-results-bucket=chromium-result-details --recover-devices --test-launcher-summary-output=/b/swarming/w/iobUjdhz/output.json I 0.000s Main command: ../../build/android/test_runner.py gtest --suite cacheinvalidation_unittests --output-directory . --runtime-deps-path gen.runtime/third_party/cacheinvalidation/cacheinvalidation_unittests__test_runner_script.runtime_deps -v --store-tombstones --gs-results-bucket=chromium-result-details --recover-devices --test-launcher-summary-output=/b/swarming/w/iobUjdhz/output.json I 0.007s Main condition '<lambda>' met I 0.008s Main condition '<lambda>' met I 3.173s TimeoutThread-1-for-prepare_device(01e1f7e6a2b5ac95) condition 'sd_card_ready' met (0.0s) I 3.795s TimeoutThread-1-for-prepare_device(01e1f7e6a2b5ac95) condition 'pm_ready' met (0.7s) I 3.828s TimeoutThread-1-for-prepare_device(01e1f7e6a2b5ac95) condition 'boot_completed' met (0.7s) I 12.199s TimeoutThread-1-for-individual_device_set_up(01e1f7e6a2b5ac95) Setting permissions for org.chromium.native_test. I 15.178s calculate_device_checksums condition '<lambda>' met (0.1s) I 17.454s list_tests(01e1f7e6a2b5ac95) flags: I 17.454s list_tests(01e1f7e6a2b5ac95) --gtest_list_tests I 18.989s list_tests(01e1f7e6a2b5ac95) /sdcard/temp_file-2e3972196a652.gtest_out size on device: 682 I 19.058s Main Using external sharding settings. This is shard 0/1 I 19.058s Main STARTING TRY #1/3 I 19.058s Main Will run 28 tests on 1 devices: 01e1f7e6a2b5ac95 W 19.123s run_tests_on_device(01e1f7e6a2b5ac95) No tombstones to clear. I 24.594s run_tests_on_device(01e1f7e6a2b5ac95) flags: I 24.594s run_tests_on_device(01e1f7e6a2b5ac95) Getting logdog client. I 26.373s run_tests_on_device(01e1f7e6a2b5ac95) /sdcard/temp_file-fd8268424c7.gtest_out size on device: 97018 I 26.690s run_tests_on_device(01e1f7e6a2b5ac95) Logcat saved to https://luci-logdog.appspot.com/v/?s=chromium%2Fandroid%2Fswarming%2Flogcats%2F43abe1a6cd442811%2F%2B%2Flogcat_logcat_-2631999291401687399_20190318T230906-UTC_01e1f7e6a2b5ac95 I 26.690s archive Writing text to logdog stream, logcat_logcat_-2631999291401687399_20190318T230906-UTC_01e1f7e6a2b5ac95 I 27.396s TimeoutThread-1-for-run_tests_on_device(01e1f7e6a2b5ac95) Setting permissions for org.chromium.native_test. I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) >>ScopedMainEntryLogger I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) 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 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [==========] Running 28 tests from 4 test suites. I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [----------] Global test environment set-up. I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [----------] 10 tests from InvalidationClientImplTest I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] InvalidationClientImplTest.Start I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f0c8 with delay 0 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f150 with delay 0 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f0c8 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f150 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f160 with delay 0 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f160 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f150 with delay 0 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f150 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1442970520 with a delay 0, Now = 210919424 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f160 with delay 0 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f160 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "8583988588494019950" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1442970328 with a delay 500000, Now = 210919424 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f150 with delay 500 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1442970520 with a delay 60000000, Now = 210919424 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f158 with delay 60000 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f150 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [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: "8583988588494019950" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f150 with delay 0 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f150 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "8583988588494019950" 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 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "8583988588494019950" I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1274170312 with a delay 1200000000, Now = 211419424 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f160 with delay 1200000 I 30.996s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1454906616 with a delay 0, Now = 211419424 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f0c8 with delay 0 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [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 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f0c8 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f170 with delay 0 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1454906616 with a delay 10000000, Now = 211419424 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f168 with delay 10000 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f170 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] InvalidationClientImplTest.Start (15 ms) I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] InvalidationClientImplTest.GenerateNonce I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f0b0 with delay 0 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] InvalidationClientImplTest.GenerateNonce (5 ms) I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] InvalidationClientImplTest.Register I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f0c8 with delay 0 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f160 with delay 0 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f0c8 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f160 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f170 with delay 0 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f170 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f160 with delay 0 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f160 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1442970232 with a delay 0, Now = 210919424 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f170 with delay 0 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f170 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "8076797106108002731" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1442970520 with a delay 500000, Now = 210919424 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f160 with delay 500 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1442970232 with a delay 60000000, Now = 210919424 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f168 with delay 60000 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f160 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [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: "8076797106108002731" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f160 with delay 0 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f160 I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "8076797106108002731" 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 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "8076797106108002731" I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 30.997s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1274170312 with a delay 1200000000, Now = 211419424 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f170 with delay 1200000 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1454906616 with a delay 0, Now = 211419424 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f0c8 with delay 0 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [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 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f0c8 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f180 with delay 0 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1454906616 with a delay 10000000, Now = 211419424 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f178 with delay 10000 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f180 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f180 with delay 0 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7fa947f180 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling -1442970520 with a delay 500000, Now = 211469424 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f0c8 with delay 500 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling -1442970040 with a delay 60000000, Now = 211469424 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f160 with delay 60000 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7fa947f0c8 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [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 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7fa947f0c8 with delay 0 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7fa947f0c8 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [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 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [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 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7fa947f178 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] InvalidationClientImplTest.Register (19 ms) I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] InvalidationClientImplTest.Invalidations I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f0b0 with delay 0 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f150 with delay 0 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f0b0 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f150 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f178 with delay 0 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f178 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f150 with delay 0 I 30.998s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f150 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1442970136 with a delay 0, Now = 210919424 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f178 with delay 0 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f178 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-5287137274781607610" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1442969848 with a delay 500000, Now = 210919424 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f150 with delay 500 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1442970136 with a delay 60000000, Now = 210919424 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f158 with delay 60000 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f150 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [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: "-5287137274781607610" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f150 with delay 0 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f150 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-5287137274781607610" 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 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-5287137274781607610" I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1274169864 with a delay 1200000000, Now = 211419424 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f178 with delay 1200000 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1454906616 with a delay 0, Now = 211419424 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f0b0 with delay 0 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [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 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f0b0 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f188 with delay 0 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1454906616 with a delay 10000000, Now = 211419424 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f180 with delay 10000 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f188 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f188 with delay 0 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7fa947f188 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [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 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [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 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [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 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [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 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [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 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7fa947f188 with delay 0 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7fa947f0b0 with delay 0 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7fa947f150 with delay 0 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7fa947f188 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Send-ack] Scheduling -1442969848 with a delay 500000, Now = 211519424 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7fa947f190 with delay 500 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7fa947f0b0 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7fa947f150 I 30.999s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x7fa947f190 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] InvalidationClientImplTest.Invalidations (19 ms) I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] InvalidationClientImplTest.ServerRequests I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f0b0 with delay 0 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f138 with delay 0 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f0b0 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f138 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f148 with delay 0 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f148 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f138 with delay 0 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f138 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1442970520 with a delay 0, Now = 210919424 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f148 with delay 0 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f148 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "7406685902212802169" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1442969368 with a delay 500000, Now = 210919424 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f138 with delay 500 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1442970520 with a delay 60000000, Now = 210919424 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f140 with delay 60000 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f138 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [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: "7406685902212802169" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f138 with delay 0 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f138 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "7406685902212802169" 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 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "7406685902212802169" I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1274169864 with a delay 1200000000, Now = 211419424 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f148 with delay 1200000 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1454906232 with a delay 0, Now = 211419424 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f0b0 with delay 0 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f0b0 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f160 with delay 0 I 31.000s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1454906232 with a delay 10000000, Now = 211419424 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f150 with delay 10000 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f160 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f160 with delay 0 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7fa947f160 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(294)] Adding subtree: { } I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling -1442969368 with a delay 500000, Now = 211469424 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f0b0 with delay 500 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7fa947f0b0 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7fa947f150 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] InvalidationClientImplTest.ServerRequests (21 ms) I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f0b8 with delay 0 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f160 with delay 0 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f0b8 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f160 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f170 with delay 0 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f170 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f160 with delay 0 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f160 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1442969848 with a delay 0, Now = 210919424 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f170 with delay 0 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f170 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-7098965218987691958" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1442970520 with a delay 500000, Now = 210919424 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f160 with delay 500 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1442969848 with a delay 60000000, Now = 210919424 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f168 with delay 60000 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f160 I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 31.001s run_tests_on_device(01e1f7e6a2b5ac95) [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: "-7098965218987691958" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f160 with delay 0 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f160 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-7098965218987691958" 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 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-7098965218987691958" I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1274169864 with a delay 1200000000, Now = 211419424 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f170 with delay 1200000 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1454906232 with a delay 0, Now = 211419424 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f0b8 with delay 0 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f0b8 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f180 with delay 0 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1454906232 with a delay 10000000, Now = 211419424 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f178 with delay 10000 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f180 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f180 with delay 0 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7fa947f180 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7fa947f178 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] InvalidationClientImplTest.IncomingErrorMessage (17 ms) I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f0b8 with delay 0 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f160 with delay 0 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f0b8 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f160 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f180 with delay 0 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f180 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f160 with delay 0 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f160 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1442970136 with a delay 0, Now = 210919424 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f180 with delay 0 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f180 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-4583721112238564475" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1442969848 with a delay 500000, Now = 210919424 I 31.002s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f160 with delay 500 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1442970136 with a delay 60000000, Now = 210919424 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f178 with delay 60000 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f160 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [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: "-4583721112238564475" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f160 with delay 0 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f160 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-4583721112238564475" 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 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-4583721112238564475" I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1274169864 with a delay 1200000000, Now = 211419424 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f180 with delay 1200000 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1454906232 with a delay 0, Now = 211419424 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f0b8 with delay 0 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f0b8 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f190 with delay 0 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1454906232 with a delay 10000000, Now = 211419424 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f188 with delay 10000 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f190 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f190 with delay 0 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7fa947f190 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling -1442969848 with a delay 500000, Now = 211469424 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f0b8 with delay 500 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling -1442970328 with a delay 60000000, Now = 211469424 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f160 with delay 60000 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7fa947f0b8 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7fa947f0b8 with delay 0 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7fa947f0b8 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7fa947f188 I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (20 ms) I 31.003s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] InvalidationClientImplTest.NetworkTimeouts I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f0b0 with delay 0 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f138 with delay 0 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f0b0 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f138 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f148 with delay 0 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f148 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f138 with delay 0 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f138 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1442970040 with a delay 0, Now = 210919424 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f148 with delay 0 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f148 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "774948709943169503" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1442970136 with a delay 500000, Now = 210919424 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f138 with delay 500 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1442970040 with a delay 60000000, Now = 210919424 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f140 with delay 60000 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f138 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [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: "774948709943169503" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f138 with delay 0 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f138 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "774948709943169503" 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 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "774948709943169503" I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1274169864 with a delay 1200000000, Now = 211419424 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f148 with delay 1200000 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1454906232 with a delay 0, Now = 211419424 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f0b0 with delay 0 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f0b0 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f158 with delay 0 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1454906232 with a delay 10000000, Now = 211419424 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f150 with delay 10000 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f158 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f158 with delay 0 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7fa947f158 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Send-registrations] Scheduling -1442970136 with a delay 500000, Now = 211469424 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f0b0 with delay 500 I 31.004s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [PerformRegister] Scheduling -1442969752 with a delay 60000000, Now = 211469424 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f138 with delay 60000 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7fa947f0b0 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7fa947f150 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7fa947f140 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x7fa947f138 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Send-info] Scheduling -1442970136 with a delay 500000, Now = 271469424 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7fa947f140 with delay 500 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1442969752 with a delay 60000000, Now = 271469424 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7fa947f150 with delay 60000 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x7fa947f140 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] InvalidationClientImplTest.NetworkTimeouts (22 ms) I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f0b8 with delay 0 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f140 with delay 0 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f0b8 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f140 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f160 with delay 0 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f160 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f140 with delay 0 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f140 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1442969944 with a delay 0, Now = 210919424 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f160 with delay 0 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f160 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-761806855886716001" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1442970232 with a delay 500000, Now = 210919424 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f140 with delay 500 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1442969944 with a delay 60000000, Now = 210919424 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f158 with delay 60000 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f140 I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 31.005s run_tests_on_device(01e1f7e6a2b5ac95) [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: "-761806855886716001" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f140 with delay 0 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f140 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-761806855886716001" 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 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-761806855886716001" I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1274170200 with a delay 1200000000, Now = 211419424 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f160 with delay 1200000 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1454906232 with a delay 0, Now = 211419424 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f0b8 with delay 0 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f0b8 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f170 with delay 0 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1454906232 with a delay 10000000, Now = 211419424 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f168 with delay 10000 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f170 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7fa947f170 with delay 0 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7fa947f170 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7fa947f168 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] InvalidationClientImplTest.NoRegistrationSummary (17 ms) I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] InvalidationClientImplTest.Heartbeats I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f0b8 with delay 0 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f140 with delay 0 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f0b8 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f140 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f150 with delay 0 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f150 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [WARNING:invalidation-client-core.cc(961)] Could not read state blob: I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f140 with delay 0 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f140 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(351)] Starting with no previous state I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1442970424 with a delay 0, Now = 210919424 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f150 with delay 0 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f150 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1338315031295081496" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [AcquireToken] Scheduling -1442969944 with a delay 500000, Now = 210919424 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f140 with delay 500 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1442970424 with a delay 60000000, Now = 210919424 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f148 with delay 60000 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f140 I 31.006s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "" I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [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: "1338315031295081496" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f140 with delay 0 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f140 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1338315031295081496" 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 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1338315031295081496" I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling -1274170200 with a delay 1200000000, Now = 211419424 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f150 with delay 1200000 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling -1454906232 with a delay 0, Now = 211419424 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f0b8 with delay 0 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f0b8 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f170 with delay 0 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1454906232 with a delay 10000000, Now = 211419424 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7fa947f168 with delay 10000 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f170 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(146)] Write state completed: 1, I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7fa947f168 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7fa947f148 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x7fa947f150 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Send-info] Scheduling -1442969944 with a delay 500000, Now = 1411419424 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7fa947f148 with delay 500 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -1274170200 with a delay 1200000000, Now = 1411419424 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7fa947f168 with delay 1200000 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x7fa947f148 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:invalidation-client-core.cc(488)] Return client token = "new token" I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] InvalidationClientImplTest.Heartbeats (27 ms) I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [----------] 10 tests from InvalidationClientImplTest (185 ms total) I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [----------] 13 tests from ProtocolHandlerTest I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ProtocolHandlerTest.SendInitializeOnly I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f048 with delay 0 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f048 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Startup] Scheduling -1442970520 with a delay 500000, Now = 210919424 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f080 with delay 500 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f080 I 31.007s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ProtocolHandlerTest.SendInitializeOnly (7 ms) I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (4 ms) I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f058 with delay 0 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f068 with delay 0 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f070 with delay 0 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f078 with delay 0 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f080 with delay 0 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f090 with delay 0 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f058 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Send-info] Scheduling -1442970136 with a delay 500000, Now = 210919424 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f0b0 with delay 500 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f068 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f070 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f078 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f080 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f090 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f0b0 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (4 ms) I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ProtocolHandlerTest.IncomingCompositeMessage (2 ms) I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ProtocolHandlerTest.InvalidInboundMessage (2 ms) I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ProtocolHandlerTest.MajorVersionMismatch (3 ms) I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ProtocolHandlerTest.MinorVersionMismatch (1 ms) I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ProtocolHandlerTest.ConfigMessage I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f058 with delay 0 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f058 I 31.008s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Send-info] Scheduling -1442970232 with a delay 500000, Now = 210919424 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f068 with delay 500 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f068 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ProtocolHandlerTest.ConfigMessage (11 ms) I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ProtocolHandlerTest.ErrorMessage I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ProtocolHandlerTest.ErrorMessage (1 ms) I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ProtocolHandlerTest.TokenMismatch I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ProtocolHandlerTest.TokenMismatch (1 ms) I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ProtocolHandlerTest.TokenMissing I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f058 with delay 0 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f058 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Send-info] Scheduling -1442969944 with a delay 500000, Now = 210919424 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f068 with delay 500 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f068 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [WARNING:protocol-handler.cc(313)] Unable to build message I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ProtocolHandlerTest.TokenMissing (3 ms) I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f058 with delay 0 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7fa947f058 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Send-ack] Scheduling -1442970232 with a delay 500000, Now = 210919424 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7fa947f068 with delay 500 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7fa947f068 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [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 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ProtocolHandlerTest.InvalidOutboundMessage (3 ms) I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:protocol-handler.cc(139)] Incoming message: { } I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ERROR:ticl-message-validator.cc(361)] required field header missing from { } I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ERROR:protocol-handler.cc(145)] Received invalid message: { } I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [----------] 13 tests from ProtocolHandlerTest (48 ms total) I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [----------] 3 tests from RecurringTaskTest I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] RecurringTaskTest.PeriodicTask I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -748146296 with a delay 10000, Now = 0 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7fa947f168 with delay 10 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7fa947f168 I 31.009s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (10000) Task running: 1 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 60000, Now = 10000 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7fa947f010 with delay 60 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x7fa947f010 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (70000) Task running: 2 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 60000, Now = 70000 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7fa947f168 with delay 60 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7fa947f168 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (130000) Task running: 3 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 60000, Now = 130000 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x7fa947f010 with delay 60 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x7fa947f010 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (190000) Task running: 4 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 60000, Now = 190000 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7fa947f168 with delay 60 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7fa947f168 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (250000) Task running: 5 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 60000, Now = 250000 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x7fa947f010 with delay 60 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x7fa947f010 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (310000) Task running: 6 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 60000, Now = 310000 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7fa947f168 with delay 60 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7fa947f168 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (370000) Task running: 7 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 60000, Now = 370000 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x7fa947f010 with delay 60 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x7fa947f010 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (430000) Task running: 8 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] RecurringTaskTest.PeriodicTask (6 ms) I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] RecurringTaskTest.ExponentialBackoffTask I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -748146296 with a delay 10000, Now = 0 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7fa947f010 with delay 10 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7fa947f010 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (10000) Task running: 1 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 50000, Now = 10000 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7fa947f168 with delay 50 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7fa947f168 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (60000) Task running: 2 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 149000, Now = 60000 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x7fa947f010 with delay 149 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x7fa947f010 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (210000) Task running: 3 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 248000, Now = 210000 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7fa947f168 with delay 248 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7fa947f168 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (460000) Task running: 4 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 446000, Now = 460000 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x7fa947f010 with delay 446 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x7fa947f010 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (910000) Task running: 5 I 31.010s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 842000, Now = 910000 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7fa947f168 with delay 842 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7fa947f168 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 1040000, Now = 1760000 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x7fa947f010 with delay 1040 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x7fa947f010 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [Retry] Scheduling -748146296 with a delay 1040000, Now = 2800000 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7fa947f168 with delay 1040 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7fa947f168 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] RecurringTaskTest.ExponentialBackoffTask (5 ms) I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] RecurringTaskTest.OneShotTask I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -748146312 with a delay 10000, Now = 0 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7fa947f168 with delay 10 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7fa947f168 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (10000) Task running: 1 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -748146312 with a delay 10000, Now = 10000 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7fa947f168 with delay 10 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7fa947f168 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:recurring-task_test.cc(71)] (20000) Task running: 2 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] RecurringTaskTest.OneShotTask (2 ms) I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [----------] 3 tests from RecurringTaskTest (14 ms total) I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [----------] 2 tests from ThrottleTest I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ThrottleTest.ThrottlingScripted I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7fa947f060 with delay 920 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7fa947f060 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7fa947f060 with delay 45000 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7fa947f060 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ThrottleTest.ThrottlingScripted (2 ms) I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [ RUN ] ThrottleTest.ThrottlingStorm I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7fa947f060 with delay 990 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7fa947f060 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7fa947f060 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7fa947f060 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7fa947f060 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7fa947f060 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7fa947f060 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x7fa947f020 with delay 54000 I 31.011s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x7fa947f020 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x7fa947f020 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x7fa947f020 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x7fa947f020 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x7fa947f020 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x7fa947f020 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7fa947f060 with delay 54000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7fa947f060 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7fa947f060 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7fa947f060 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7fa947f060 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7fa947f060 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7fa947f060 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7fa947f060 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x7fa947f020 with delay 54000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x7fa947f020 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x7fa947f020 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x7fa947f020 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x7fa947f020 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x7fa947f020 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x7fa947f020 with delay 1000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x7fa947f020 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7fa947f060 with delay 54000 I 31.012s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7fa947f060 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7fa947f060 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7fa947f060 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7fa947f060 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7fa947f060 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7fa947f060 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7fa947f060 with delay 1000 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7fa947f060 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x7fa947f020 with delay 54000 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x7fa947f020 I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [ OK ] ThrottleTest.ThrottlingStorm (12 ms) I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [----------] 2 tests from ThrottleTest (14 ms total) I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [----------] Global test environment tear-down I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [==========] 28 tests from 4 test suites ran. (264 ms total) I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) [ PASSED ] 28 tests. I 31.013s run_tests_on_device(01e1f7e6a2b5ac95) <<ScopedMainEntryLogger I 31.015s run_tests_on_device(01e1f7e6a2b5ac95) Finished running tests on this device. I 31.034s Main FINISHED TRY #1/3 I 31.034s Main All tests completed. C 31.035s Main ******************************************************************************** C 31.035s Main Summary C 31.035s Main ******************************************************************************** C 31.035s Main [==========] 28 tests ran. C 31.035s Main [ PASSED ] 28 tests. C 31.035s Main ******************************************************************************** I 31.036s tear_down_device(01e1f7e6a2b5ac95) Wrote device cache: /b/swarming/w/ir/out/Release/device_cache_01e1f7e6a2b5ac95.json I 31.038s Main Generated json results file at /b/swarming/w/itQSYo_K/tmpPIyUU2 I 31.038s Main Finishing archiving output. [W2019-03-18T23:09:12.817652Z 17110 0 butler.go:240] Butler Context was cancelled. Initiating shutdown. {"error":"context canceled"} INFO:devil.utils.timeout_retry:condition 'logdog_stopped' not met [E2019-03-18T23:09:12.921274Z 17110 0 main.go:205] Butler terminated with error. {"error":"context canceled"} [E2019-03-18T23:09:12.921308Z 17110 0 main.go:233] Failed to serve. original error: context canceled [I2019-03-18T23:09:12.921358Z 17110 0 main.go:349] Terminating. {"returnCode":250} INFO:devil.utils.timeout_retry:condition 'logdog_stopped' met 2019-03-19 00:40:17,500 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmpsX9YTQ/43adb1265962dd10'] 2019-03-19 00:40:17,501 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmpsX9YTQ/43adb1265962dd10/output.json'] 2019-03-19 00:40:17,501 - 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 {"bot_id": "swarm1596-c4", "branch": "refs/heads/master", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552978929671795, "id": "8918577281799034752", "project": "chromium", "tags": ["build_address:luci.chromium.ci/android-marshmallow-arm64-rel/13567", "builder:android-marshmallow-arm64-rel", "buildset:commit/git/ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "gitiles_ref:refs/heads/master", "scheduler_invocation_id:9084007344139014192", "scheduler_job_id:chromium/android-marshmallow-arm64-rel", "user_agent:luci-scheduler"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "android-marshmallow-arm64-rel", "buildnumber": 13567, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "got_revision_cp": "refs/heads/master@{#641821}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "repository": "https://chromium.googlesource.com/chromium/src.git", "revision": "ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc"} --summary-json /b/swarming/w/ir/tmp/t/tmpO1j5Vj.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpsX9YTQ --bucket chromium-result-details --test-name cacheinvalidation_unittests -o /b/swarming/w/ir/tmp/t/tmpz9l8kr.json /b/swarming/w/ir/tmp/t/tmpsX9YTQ/43adb1265962dd10/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', '{"bot_id": "swarm1596-c4", "branch": "refs/heads/master", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552978929671795, "id": "8918577281799034752", "project": "chromium", "tags": ["build_address:luci.chromium.ci/android-marshmallow-arm64-rel/13567", "builder:android-marshmallow-arm64-rel", "buildset:commit/git/ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "gitiles_ref:refs/heads/master", "scheduler_invocation_id:9084007344139014192", "scheduler_job_id:chromium/android-marshmallow-arm64-rel", "user_agent:luci-scheduler"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "android-marshmallow-arm64-rel", "buildnumber": 13567, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "got_revision_cp": "refs/heads/master@{#641821}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "repository": "https://chromium.googlesource.com/chromium/src.git", "revision": "ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc"}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpO1j5Vj.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpsX9YTQ', u'--bucket', u'chromium-result-details', u'--test-name', u'cacheinvalidation_unittests', '-o', '/b/swarming/w/ir/tmp/t/tmpz9l8kr.json', '/b/swarming/w/ir/tmp/t/tmpsX9YTQ/43adb1265962dd10/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', '{"bot_id": "swarm1596-c4", "branch": "refs/heads/master", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552978929671795, "id": "8918577281799034752", "project": "chromium", "tags": ["build_address:luci.chromium.ci/android-marshmallow-arm64-rel/13567", "builder:android-marshmallow-arm64-rel", "buildset:commit/git/ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "gitiles_ref:refs/heads/master", "scheduler_invocation_id:9084007344139014192", "scheduler_job_id:chromium/android-marshmallow-arm64-rel", "user_agent:luci-scheduler"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "android-marshmallow-arm64-rel", "buildnumber": 13567, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc", "got_revision_cp": "refs/heads/master@{#641821}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.android", "path_config": "generic", "recipe": "chromium", "repository": "https://chromium.googlesource.com/chromium/src.git", "revision": "ef02d41b19e5c2cf79f35a588b72d2f5ebbb9fcc"}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpO1j5Vj.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpsX9YTQ', u'--bucket', u'chromium-result-details', u'--test-name', u'cacheinvalidation_unittests', '-o', '/b/swarming/w/ir/tmp/t/tmpz9l8kr.json', '/b/swarming/w/ir/tmp/t/tmpsX9YTQ/43adb1265962dd10/output.json'] returned exit code 0