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/tmp3ywz1X.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpvPSR0l --merge-script /b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --merge-script-stdout-file /b/swarming/w/ir/tmp/t/tmp9qa_oimerge_script_log --merge-additional-args '[]' --build-properties '{"blamelist": ["pcc@chromium.org"], "bot_id": "swarm1906-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:pcc@google.com", "created_ts": 1553807815101901, "id": "8917708132430700752", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1411", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1534187/4", "user_agent:git_cl_try"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1411, "category": "git_cl_try", "got_angle_revision": "2e5afde1d68b68ab543e508c311c94f09921c07c", "got_dawn_revision": "19179e180b2e04990a725b038782e40b80fa75f3", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "8f3cd84f6cadd65279873b6834e843778ff9976a", "got_revision_cp": "refs/heads/master@{#645503}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "370905e268aed09b47e08d593d95f4f31f79cfc6", "got_v8_revision_cp": "refs/heads/7.5.138@{#1}", "got_webrtc_revision": "4c7112a27a535990ed7d7a6d990391ca7ffdc3eb", "got_webrtc_revision_cp": "refs/heads/master@{#27348}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1534187, "patch_project": "chromium/src", "patch_ref": "refs/changes/87/1534187/4", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 4, "patch_storage": "gerrit", "path_config": "generic", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src"}' --summary-json-file /b/swarming/w/ir/tmp/t/tmp6Yyp4b.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/tmpYMm8Du.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/tmp3ywz1X.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpvPSR0l', '--merge-script', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--merge-script-stdout-file', '/b/swarming/w/ir/tmp/t/tmp9qa_oimerge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"blamelist": ["pcc@chromium.org"], "bot_id": "swarm1906-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:pcc@google.com", "created_ts": 1553807815101901, "id": "8917708132430700752", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1411", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1534187/4", "user_agent:git_cl_try"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1411, "category": "git_cl_try", "got_angle_revision": "2e5afde1d68b68ab543e508c311c94f09921c07c", "got_dawn_revision": "19179e180b2e04990a725b038782e40b80fa75f3", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "8f3cd84f6cadd65279873b6834e843778ff9976a", "got_revision_cp": "refs/heads/master@{#645503}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "370905e268aed09b47e08d593d95f4f31f79cfc6", "got_v8_revision_cp": "refs/heads/7.5.138@{#1}", "got_webrtc_revision": "4c7112a27a535990ed7d7a6d990391ca7ffdc3eb", "got_webrtc_revision_cp": "refs/heads/master@{#27348}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1534187, "patch_project": "chromium/src", "patch_ref": "refs/changes/87/1534187/4", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 4, "patch_storage": "gerrit", "path_config": "generic", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src"}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmp6Yyp4b.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/tmpYMm8Du.json'] env: {'CHROME_HEADLESS': '1'} env_prefixes: {'PATH': '/b/swarming/w/ir/cache/swarming_client'} env_suffixes: {} infra_step: False name_tokens: ('cacheinvalidation_unittests (with patch)',) ok_ret: ALL_OK step_test_data: gen_default_step_test_data(...) 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: 44097 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/8917708132430700752 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/itVtK7Dp/luci_context.087388911 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/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: swarm1906-c4 SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 43defb487d0a2c11 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-28 15:31:15,491 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmpvPSR0l' 2019-03-28 15:31:15,491 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmpvPSR0l' already exists! 2019-03-28 15:31:15,491 - root: [WARNING] task_output_dir existing content: [] 2019-03-28 15:31:15,491 - 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/tmpYMm8Du.json -output-dir /b/swarming/w/ir/tmp/t/tmpvPSR0l -task-summary-json /b/swarming/w/ir/tmp/t/tmp6Yyp4b.json [D2019-03-28T15:31:15.498174-07:00 2739 0 auth.go:1265] Minting a new token {"key":"luci_ctx/eb110a7544dd438c5a63f2a0cabed87598e9a2a997ce78600d979ec34cb37047", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-28T15:31:15.498261-07:00 2739 0 luci_ctx.go:138] POST http://127.0.0.1:40964/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/eb110a7544dd438c5a63f2a0cabed87598e9a2a997ce78600d979ec34cb37047", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-28T15:31:15.500108-07:00 2739 0 auth.go:1222] Token expires in 43m53.499916013s {"key":"luci_ctx/eb110a7544dd438c5a63f2a0cabed87598e9a2a997ce78600d979ec34cb37047", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 43df3d6feaf09f10: exit 0 Additional test environment: CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox CHROME_HEADLESS=1 G_SLICE=always-malloc LANG=en_US.UTF-8 LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer MSAN_OPTIONS=symbolize=0 handle_abort=1 NSS_DISABLE_ARENA_FREE_LIST=1 NSS_DISABLE_UNLOAD=1 Command: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioSLRNAZ/output.json IMPORTANT DEBUGGING NOTE: batches of tests are run inside their own process. For debugging a test inside a debugger, use the --gtest_filter=<your_test_name> flag along with --single-process-tests. Using sharding settings from environment. This is shard 0/1 Using 8 parallel jobs. [ RUN ] ProtocolHandlerTest.TokenMissing [18897:18897:0328/144235.890259:20666044872:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b60 with delay 0 [18897:18897:0328/144235.890330:20666044945:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b60 [18897:18897:0328/144235.890678:20666045288: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 } [18897:18897:0328/144235.890738:20666045348:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9224 with a delay 500000, Now = 210919424 [18897:18897:0328/144235.890781:20666045390:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 500 [18897:18897:0328/144235.890833:20666045442:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b70 [18897:18897:0328/144235.890932:20666045550:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [18897:18897:0328/144235.890981:20666045592:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (2 ms) [1/28] ProtocolHandlerTest.TokenMissing (2 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [18897:18897:0328/144235.891486:20666046097:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 0 [18897:18897:0328/144235.891530:20666046141:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b70 [18897:18897:0328/144235.891574:20666046192:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9320 with a delay 500000, Now = 210919424 [18897:18897:0328/144235.891624:20666046240:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b60 with delay 500 [18897:18897:0328/144235.891684:20666046293:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b60 [18897:18897:0328/144235.891795:20666046406:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [18897:18897:0328/144235.891887:20666046497: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 } [18897:18897:0328/144235.891963:20666046574: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 } } [18897:18897:0328/144235.892098:20666046709: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 } } } [18897:18897:0328/144235.892230:20666046842: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 } } } [ OK ] ProtocolHandlerTest.InvalidOutboundMessage (1 ms) [2/28] ProtocolHandlerTest.InvalidOutboundMessage (1 ms) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage [18897:18897:0328/144235.892662:20666047282:INFO:protocol-handler.cc(139)] Incoming message: { } [18897:18897:0328/144235.892720:20666047330:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [18897:18897:0328/144235.892760:20666047372:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [3/28] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [ RUN ] RecurringTaskTest.PeriodicTask [18897:18897:0328/144235.893021:20666047631:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 2057095176 with a delay 10000, Now = 0 [18897:18897:0328/144235.893062:20666047676:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009d0 with delay 10 [18897:18897:0328/144235.893118:20666047728:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009d0 [18897:18897:0328/144235.893155:20666047767:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [18897:18897:0328/144235.893194:20666047804:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057095176 with a delay 60000, Now = 10000 [18897:18897:0328/144235.893235:20666047844:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009e0 with delay 60 [18897:18897:0328/144235.893274:20666047883:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x7010000009e0 [18897:18897:0328/144235.893306:20666047914:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [18897:18897:0328/144235.893338:20666047946:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057095176 with a delay 60000, Now = 70000 [18897:18897:0328/144235.893370:20666047978:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7010000009d0 with delay 60 [18897:18897:0328/144235.893404:20666048034:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7010000009d0 [18897:18897:0328/144235.893480:20666048089:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [18897:18897:0328/144235.893513:20666048122:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057095176 with a delay 60000, Now = 130000 [18897:18897:0328/144235.893546:20666048155:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x7010000009e0 with delay 60 [18897:18897:0328/144235.893581:20666048189:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x7010000009e0 [18897:18897:0328/144235.893613:20666048221:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [18897:18897:0328/144235.893645:20666048253:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057095176 with a delay 60000, Now = 190000 [18897:18897:0328/144235.893677:20666048286:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7010000009d0 with delay 60 [18897:18897:0328/144235.893712:20666048321:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7010000009d0 [18897:18897:0328/144235.893744:20666048353:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [18897:18897:0328/144235.893776:20666048385:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057095176 with a delay 60000, Now = 250000 [18897:18897:0328/144235.893808:20666048417:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x7010000009e0 with delay 60 [18897:18897:0328/144235.893842:20666048451:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x7010000009e0 [18897:18897:0328/144235.893882:20666048491:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [18897:18897:0328/144235.893914:20666048523:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057095176 with a delay 60000, Now = 310000 [18897:18897:0328/144235.893947:20666048560:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7010000009d0 with delay 60 [18897:18897:0328/144235.893986:20666048594:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7010000009d0 [18897:18897:0328/144235.894022:20666048631:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [18897:18897:0328/144235.894054:20666048663:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057095176 with a delay 60000, Now = 370000 [18897:18897:0328/144235.894086:20666048695:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x7010000009e0 with delay 60 [18897:18897:0328/144235.894121:20666048731:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x7010000009e0 [18897:18897:0328/144235.894158:20666048769:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (3 ms) [4/28] RecurringTaskTest.PeriodicTask (3 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [18897:18897:0328/144235.895403:20666050013:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 2057094992 with a delay 10000, Now = 0 [18897:18897:0328/144235.895445:20666050057:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009e0 with delay 10 [18897:18897:0328/144235.895491:20666050100:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009e0 [18897:18897:0328/144235.895530:20666050143:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [18897:18897:0328/144235.895570:20666050180:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057094992 with a delay 50000, Now = 10000 [18897:18897:0328/144235.895620:20666050231:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009d0 with delay 50 [18897:18897:0328/144235.895666:20666050275:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7010000009d0 [18897:18897:0328/144235.895702:20666050311:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [18897:18897:0328/144235.895737:20666050348:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057094992 with a delay 149000, Now = 60000 [18897:18897:0328/144235.895774:20666050385:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x7010000009e0 with delay 149 [18897:18897:0328/144235.895815:20666050424:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x7010000009e0 [18897:18897:0328/144235.895851:20666050461:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [18897:18897:0328/144235.895917:20666050533:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057094992 with a delay 248000, Now = 210000 [18897:18897:0328/144235.895984:20666050593:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7010000009d0 with delay 248 [18897:18897:0328/144235.896026:20666050637:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7010000009d0 [18897:18897:0328/144235.896062:20666050671:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [18897:18897:0328/144235.896099:20666050708:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057094992 with a delay 446000, Now = 460000 [18897:18897:0328/144235.896137:20666050746:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x7010000009e0 with delay 446 [18897:18897:0328/144235.896185:20666050800:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x7010000009e0 [18897:18897:0328/144235.896228:20666050841:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [18897:18897:0328/144235.896267:20666050882:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057094992 with a delay 842000, Now = 910000 [18897:18897:0328/144235.896314:20666050924:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7010000009d0 with delay 842 [18897:18897:0328/144235.896374:20666050982:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7010000009d0 [18897:18897:0328/144235.896405:20666051013:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [18897:18897:0328/144235.896437:20666051046:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057094992 with a delay 1040000, Now = 1760000 [18897:18897:0328/144235.896472:20666051080:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x7010000009e0 with delay 1040 [18897:18897:0328/144235.896526:20666051135:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x7010000009e0 [18897:18897:0328/144235.896558:20666051166:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [18897:18897:0328/144235.896594:20666051202:INFO:recurring-task.cc(55)] [Retry] Scheduling 2057094992 with a delay 1040000, Now = 2800000 [18897:18897:0328/144235.896625:20666051233:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7010000009d0 with delay 1040 [18897:18897:0328/144235.896680:20666051288:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7010000009d0 [18897:18897:0328/144235.896711:20666051319:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (2 ms) [5/28] RecurringTaskTest.ExponentialBackoffTask (2 ms) [ RUN ] RecurringTaskTest.OneShotTask [18897:18897:0328/144235.897854:20666052473:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 2057095032 with a delay 10000, Now = 0 [18897:18897:0328/144235.897905:20666052514:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009d0 with delay 10 [18897:18897:0328/144235.897945:20666052559:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009d0 [18897:18897:0328/144235.897988:20666052598:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [18897:18897:0328/144235.898030:20666052641:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 2057095032 with a delay 10000, Now = 10000 [18897:18897:0328/144235.898069:20666052680:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009d0 with delay 10 [18897:18897:0328/144235.898106:20666052715:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7010000009d0 [18897:18897:0328/144235.898143:20666052752:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (2 ms) [6/28] RecurringTaskTest.OneShotTask (2 ms) [ RUN ] ThrottleTest.ThrottlingScripted [18897:18897:0328/144235.899383:20666053996:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7010000009d0 with delay 920 [18897:18897:0328/144235.899450:20666054060:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009d0 [18897:18897:0328/144235.899782:20666054391:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7010000009d0 with delay 45000 [18897:18897:0328/144235.900811:20666055421:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000009d0 [ OK ] ThrottleTest.ThrottlingScripted (1 ms) [7/28] ThrottleTest.ThrottlingScripted (1 ms) [ RUN ] ThrottleTest.ThrottlingStorm [18897:18897:0328/144235.900958:20666055569:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009d0 with delay 990 [18897:18897:0328/144235.901025:20666055634:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009d0 [18897:18897:0328/144235.901064:20666055672:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.901145:20666055753:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7010000009d0 [18897:18897:0328/144235.901179:20666055787:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.901240:20666055848:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7010000009d0 [18897:18897:0328/144235.901274:20666055882:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.901336:20666055944:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7010000009d0 [18897:18897:0328/144235.901370:20666055978:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.901445:20666056055:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7010000009d0 [18897:18897:0328/144235.901484:20666056092:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.901545:20666056153:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7010000009d0 [18897:18897:0328/144235.901580:20666056190:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x7010000009e0 with delay 54000 [18897:18897:0328/144235.903229:20666057837:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000009e0 [18897:18897:0328/144235.903265:20666057873:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x7010000009e0 with delay 1000 [18897:18897:0328/144235.903325:20666057932:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x7010000009e0 [18897:18897:0328/144235.903359:20666057967:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x7010000009e0 with delay 1000 [18897:18897:0328/144235.903418:20666058026:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x7010000009e0 [18897:18897:0328/144235.903453:20666058060:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x7010000009e0 with delay 1000 [18897:18897:0328/144235.903512:20666058119:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x7010000009e0 [18897:18897:0328/144235.903545:20666058152:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x7010000009e0 with delay 1000 [18897:18897:0328/144235.903603:20666058211:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x7010000009e0 [18897:18897:0328/144235.903635:20666058243:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x7010000009e0 with delay 1000 [18897:18897:0328/144235.903695:20666058302:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x7010000009e0 [18897:18897:0328/144235.903731:20666058339:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x7010000009e0 with delay 1000 [18897:18897:0328/144235.903793:20666058400:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x7010000009e0 [18897:18897:0328/144235.903825:20666058433:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7010000009d0 with delay 54000 [18897:18897:0328/144235.905473:20666060081:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7010000009d0 [18897:18897:0328/144235.905510:20666060118:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.905570:20666060177:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7010000009d0 [18897:18897:0328/144235.905602:20666060210:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.905661:20666060268:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7010000009d0 [18897:18897:0328/144235.905693:20666060302:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.905752:20666060360:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7010000009d0 [18897:18897:0328/144235.905785:20666060393:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.905853:20666060461:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7010000009d0 [18897:18897:0328/144235.905893:20666060501:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.905955:20666060563:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7010000009d0 [18897:18897:0328/144235.905988:20666060596:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.906047:20666060655:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7010000009d0 [18897:18897:0328/144235.906079:20666060687:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x7010000009e0 with delay 54000 [18897:18897:0328/144235.907738:20666062346:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x7010000009e0 [18897:18897:0328/144235.907770:20666062378:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x7010000009e0 with delay 1000 [18897:18897:0328/144235.907846:20666062453:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x7010000009e0 [18897:18897:0328/144235.907888:20666062496:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x7010000009e0 with delay 1000 [18897:18897:0328/144235.907947:20666062559:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x7010000009e0 [18897:18897:0328/144235.907985:20666062593:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x7010000009e0 with delay 1000 [18897:18897:0328/144235.908043:20666062651:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x7010000009e0 [18897:18897:0328/144235.908076:20666062684:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x7010000009e0 with delay 1000 [18897:18897:0328/144235.908146:20666062752:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x7010000009e0 [18897:18897:0328/144235.908176:20666062783:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x7010000009e0 with delay 1000 [18897:18897:0328/144235.908230:20666062837:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x7010000009e0 [18897:18897:0328/144235.908260:20666062867:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x7010000009e0 with delay 1000 [18897:18897:0328/144235.908315:20666062922:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x7010000009e0 [18897:18897:0328/144235.908346:20666062953:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7010000009d0 with delay 54000 [18897:18897:0328/144235.909891:20666064499:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7010000009d0 [18897:18897:0328/144235.909926:20666064533:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.909985:20666064592:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7010000009d0 [18897:18897:0328/144235.910035:20666064643:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.910094:20666064701:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7010000009d0 [18897:18897:0328/144235.910126:20666064734:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.910186:20666064793:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7010000009d0 [18897:18897:0328/144235.910218:20666064826:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.910277:20666064885:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7010000009d0 [18897:18897:0328/144235.910310:20666064918:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.910369:20666064976:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7010000009d0 [18897:18897:0328/144235.910402:20666065010:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7010000009d0 with delay 1000 [18897:18897:0328/144235.910463:20666065070:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7010000009d0 [18897:18897:0328/144235.910495:20666065103:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x7010000009e0 with delay 54000 [18897:18897:0328/144235.912050:20666066658:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x7010000009e0 [ OK ] ThrottleTest.ThrottlingStorm (12 ms) [8/28] ThrottleTest.ThrottlingStorm (12 ms) [ RUN ] InvalidationClientImplTest.Start [18893:18893:0328/144235.857803:20666012425:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c60 with delay 0 [18893:18893:0328/144235.858202:20666012814:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [18893:18893:0328/144235.858647:20666013276:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e30 with delay 0 [18893:18893:0328/144235.858726:20666013343:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c60 [18893:18893:0328/144235.858789:20666013397:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e30 [18893:18893:0328/144235.858903:20666013515:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [18893:18893:0328/144235.859021:20666013636:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e80 with delay 0 [18893:18893:0328/144235.859087:20666013696:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e80 [18893:18893:0328/144235.859138:20666013750:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [18893:18893:0328/144235.859194:20666013808:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e30 with delay 0 [18893:18893:0328/144235.859245:20666013854:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e30 [18893:18893:0328/144235.859292:20666013915:INFO:invalidation-client-core.cc(351)] Starting with no previous state [18893:18893:0328/144235.859353:20666013964:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 0, Now = 210919424 [18893:18893:0328/144235.859402:20666014018:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e80 with delay 0 [18893:18893:0328/144235.859467:20666014076:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e80 [18893:18893:0328/144235.859570:20666014181:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "7703042846616005255" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [18893:18893:0328/144235.859627:20666014249:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9416 with a delay 500000, Now = 210919424 [18893:18893:0328/144235.859682:20666014297:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e30 with delay 500 [18893:18893:0328/144235.859731:20666014344:INFO:recurring-task.cc(55)] [Retry] Scheduling 9224 with a delay 60000000, Now = 210919424 [18893:18893:0328/144235.859782:20666014400:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000df0 with delay 60000 [18893:18893:0328/144235.859852:20666014477:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e30 [18893:18893:0328/144235.859930:20666014558:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.860039:20666014656:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.860257:20666014868: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: "7703042846616005255" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [18893:18893:0328/144235.860501:20666015118:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e30 with delay 0 [18893:18893:0328/144235.860562:20666015173:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e30 [18893:18893:0328/144235.860738:20666015349:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "7703042846616005255" 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" } } [18893:18893:0328/144235.860824:20666015435:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "7703042846616005255" [18893:18893:0328/144235.860880:20666015495:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [18893:18893:0328/144235.860940:20666015556:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [18893:18893:0328/144235.860998:20666015609:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e70 with delay 1200000 [18893:18893:0328/144235.861050:20666015666:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [18893:18893:0328/144235.861268:20666015883:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [18893:18893:0328/144235.861333:20666015945:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424 [18893:18893:0328/144235.861379:20666015994:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e80 with delay 0 [18893:18893:0328/144235.861493:20666016110: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 [18893:18893:0328/144235.861566:20666016176:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e80 [18893:18893:0328/144235.861674:20666016289:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ea0 with delay 0 [18893:18893:0328/144235.861733:20666016344:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424 [18893:18893:0328/144235.861772:20666016386:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c60 with delay 10000 [18893:18893:0328/144235.861818:20666016427:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ea0 [18893:18893:0328/144235.861853:20666016475:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (6 ms) [9/28] InvalidationClientImplTest.Start (6 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [18893:18893:0328/144235.862708:20666017320:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0 [18893:18893:0328/144235.862776:20666017386:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [ OK ] InvalidationClientImplTest.GenerateNonce (1 ms) [10/28] InvalidationClientImplTest.GenerateNonce (1 ms) [ RUN ] InvalidationClientImplTest.Register [18893:18893:0328/144235.863333:20666017951:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e60 with delay 0 [18893:18893:0328/144235.863419:20666018038:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [18893:18893:0328/144235.863919:20666018545:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ec0 with delay 0 [18893:18893:0328/144235.864021:20666018650:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e60 [18893:18893:0328/144235.864106:20666018726:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ec0 [18893:18893:0328/144235.864226:20666018863:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [18893:18893:0328/144235.864351:20666018963:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f00 with delay 0 [18893:18893:0328/144235.864409:20666019018:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f00 [18893:18893:0328/144235.864449:20666019065:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [18893:18893:0328/144235.864508:20666019119:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ec0 with delay 0 [18893:18893:0328/144235.864551:20666019160:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ec0 [18893:18893:0328/144235.864586:20666019203:INFO:invalidation-client-core.cc(351)] Starting with no previous state [18893:18893:0328/144235.864649:20666019272:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424 [18893:18893:0328/144235.864709:20666019325:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f00 with delay 0 [18893:18893:0328/144235.864757:20666019366:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f00 [18893:18893:0328/144235.864835:20666019446:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "7027889763865245236" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [18893:18893:0328/144235.864890:20666019506:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9224 with a delay 500000, Now = 210919424 [18893:18893:0328/144235.864946:20666019557:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ec0 with delay 500 [18893:18893:0328/144235.864990:20666019601:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424 [18893:18893:0328/144235.865033:20666019643:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 60000 [18893:18893:0328/144235.865085:20666019696:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ec0 [18893:18893:0328/144235.865131:20666019745:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.865192:20666019803:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.865351:20666019962: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: "7027889763865245236" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [18893:18893:0328/144235.865553:20666020169:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ec0 with delay 0 [18893:18893:0328/144235.865621:20666020232:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ec0 [18893:18893:0328/144235.865780:20666020391:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "7027889763865245236" 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" } } [18893:18893:0328/144235.865881:20666020494:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "7027889763865245236" [18893:18893:0328/144235.865928:20666020551:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [18893:18893:0328/144235.865994:20666020614:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [18893:18893:0328/144235.866064:20666020681:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ef0 with delay 1200000 [18893:18893:0328/144235.866130:20666020744:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [18893:18893:0328/144235.866294:20666020921:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [18893:18893:0328/144235.866363:20666020977:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424 [18893:18893:0328/144235.866413:20666021026:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f00 with delay 0 [18893:18893:0328/144235.866483:20666021094: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 [18893:18893:0328/144235.866535:20666021144:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f00 [18893:18893:0328/144235.866611:20666021221:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0 [18893:18893:0328/144235.866667:20666021282:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424 [18893:18893:0328/144235.866721:20666021331:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e60 with delay 10000 [18893:18893:0328/144235.866762:20666021370:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20 [18893:18893:0328/144235.866795:20666021416:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [18893:18893:0328/144235.866913:20666021523:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f20 with delay 0 [18893:18893:0328/144235.866953:20666021565:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f20 [18893:18893:0328/144235.867005:20666021622:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [18893:18893:0328/144235.867081:20666021690:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [18893:18893:0328/144235.867124:20666021732:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [18893:18893:0328/144235.867221:20666021833:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9224 with a delay 500000, Now = 211469424 [18893:18893:0328/144235.867269:20666021879:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f00 with delay 500 [18893:18893:0328/144235.867315:20666021926:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9704 with a delay 60000000, Now = 211469424 [18893:18893:0328/144235.867357:20666021967:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f10 with delay 60000 [18893:18893:0328/144235.867417:20666022034:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f00 [18893:18893:0328/144235.867476:20666022086:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.867535:20666022154:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.867586:20666022206:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [18893:18893:0328/144235.867794:20666022418: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 } } } [18893:18893:0328/144235.867930:20666022541:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.868029:20666022646:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f00 with delay 0 [18893:18893:0328/144235.868084:20666022695:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f00 [18893:18893:0328/144235.868362:20666022973: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 } } } } [18893:18893:0328/144235.868483:20666023102: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 [18893:18893:0328/144235.868600:20666023211:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [18893:18893:0328/144235.868731:20666023340:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [18893:18893:0328/144235.868828:20666023436:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [18893:18893:0328/144235.869138:20666023758:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e60 [ OK ] InvalidationClientImplTest.Register (7 ms) [11/28] InvalidationClientImplTest.Register (7 ms) [ RUN ] InvalidationClientImplTest.Invalidations [18893:18893:0328/144235.870803:20666025426:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000da0 with delay 0 [18893:18893:0328/144235.870892:20666025501:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [18893:18893:0328/144235.871282:20666025897:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c10 with delay 0 [18893:18893:0328/144235.871342:20666025958:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000da0 [18893:18893:0328/144235.871394:20666026002:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c10 [18893:18893:0328/144235.871463:20666026077:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [18893:18893:0328/144235.871542:20666026153:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0 [18893:18893:0328/144235.871593:20666026202:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20 [18893:18893:0328/144235.871628:20666026245:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [18893:18893:0328/144235.871685:20666026295:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c10 with delay 0 [18893:18893:0328/144235.871723:20666026332:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c10 [18893:18893:0328/144235.871758:20666026379:INFO:invalidation-client-core.cc(351)] Starting with no previous state [18893:18893:0328/144235.871819:20666026430:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424 [18893:18893:0328/144235.871863:20666026482:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0 [18893:18893:0328/144235.871913:20666026522:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20 [18893:18893:0328/144235.871986:20666026596:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-6314295299458605816" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [18893:18893:0328/144235.872035:20666026653:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424 [18893:18893:0328/144235.872088:20666026699:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c10 with delay 500 [18893:18893:0328/144235.872126:20666026739:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424 [18893:18893:0328/144235.872167:20666026780:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 60000 [18893:18893:0328/144235.872219:20666026829:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c10 [18893:18893:0328/144235.872263:20666026874:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.872316:20666026929:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.872455:20666027065: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: "-6314295299458605816" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [18893:18893:0328/144235.872589:20666027204:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c10 with delay 0 [18893:18893:0328/144235.872635:20666027246:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c10 [18893:18893:0328/144235.872772:20666027385:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-6314295299458605816" 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" } } [18893:18893:0328/144235.872846:20666027457:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-6314295299458605816" [18893:18893:0328/144235.872900:20666027511:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [18893:18893:0328/144235.872951:20666027567:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [18893:18893:0328/144235.873009:20666027619:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ec0 with delay 1200000 [18893:18893:0328/144235.873053:20666027665:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [18893:18893:0328/144235.873181:20666027792:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [18893:18893:0328/144235.873231:20666027841:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424 [18893:18893:0328/144235.873278:20666027889:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0 [18893:18893:0328/144235.873343:20666027953: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 [18893:18893:0328/144235.873394:20666028022:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20 [18893:18893:0328/144235.873496:20666028106:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f50 with delay 0 [18893:18893:0328/144235.873543:20666028156:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424 [18893:18893:0328/144235.873590:20666028202:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000da0 with delay 10000 [18893:18893:0328/144235.873630:20666028239:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f50 [18893:18893:0328/144235.873670:20666028281:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [18893:18893:0328/144235.873739:20666028350:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.873822:20666028438:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f50 with delay 0 [18893:18893:0328/144235.873878:20666028489:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f50 [18893:18893:0328/144235.874100:20666028711: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 } } } [18893:18893:0328/144235.874194:20666028814: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 [18893:18893:0328/144235.874292:20666028903: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" } [18893:18893:0328/144235.874443:20666029052:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [18893:18893:0328/144235.874541:20666029150:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [18893:18893:0328/144235.874638:20666029249:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f50 with delay 0 [18893:18893:0328/144235.874681:20666029294:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f20 with delay 0 [18893:18893:0328/144235.874722:20666029342:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f30 with delay 0 [18893:18893:0328/144235.874778:20666029395:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f50 [18893:18893:0328/144235.874854:20666029472:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9896 with a delay 500000, Now = 211519424 [18893:18893:0328/144235.874916:20666029527:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000c10 with delay 500 [18893:18893:0328/144235.874961:20666029570:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f20 [18893:18893:0328/144235.875004:20666029612:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f30 [18893:18893:0328/144235.875056:20666029667:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x701000000c10 [18893:18893:0328/144235.875098:20666029709:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.875160:20666029770:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.875201:20666029811:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [18893:18893:0328/144235.875399:20666030016: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 } } } [ OK ] InvalidationClientImplTest.Invalidations (5 ms) [12/28] InvalidationClientImplTest.Invalidations (5 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [18893:18893:0328/144235.876168:20666030779:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e90 with delay 0 [18893:18893:0328/144235.876233:20666030842:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [18893:18893:0328/144235.876491:20666031106:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000cf0 with delay 0 [18893:18893:0328/144235.876539:20666031159:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e90 [18893:18893:0328/144235.876591:20666031200:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000cf0 [18893:18893:0328/144235.876665:20666031276:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [18893:18893:0328/144235.876728:20666031339:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f00 with delay 0 [18893:18893:0328/144235.876776:20666031385:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f00 [18893:18893:0328/144235.876818:20666031428:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [18893:18893:0328/144235.876859:20666031479:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000cf0 with delay 0 [18893:18893:0328/144235.876907:20666031516:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000cf0 [18893:18893:0328/144235.876943:20666031557:INFO:invalidation-client-core.cc(351)] Starting with no previous state [18893:18893:0328/144235.876993:20666031607:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424 [18893:18893:0328/144235.877039:20666031650:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f00 with delay 0 [18893:18893:0328/144235.877080:20666031689:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f00 [18893:18893:0328/144235.877152:20666031762:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-3256872375598085327" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [18893:18893:0328/144235.877203:20666031813:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424 [18893:18893:0328/144235.877244:20666031854:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000cf0 with delay 500 [18893:18893:0328/144235.877281:20666031895:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424 [18893:18893:0328/144235.877329:20666031942:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d20 with delay 60000 [18893:18893:0328/144235.877380:20666031991:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000cf0 [18893:18893:0328/144235.877448:20666032059:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.877506:20666032125:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.877660:20666032271: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: "-3256872375598085327" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [18893:18893:0328/144235.877786:20666032411:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000cf0 with delay 0 [18893:18893:0328/144235.877844:20666032457:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000cf0 [18893:18893:0328/144235.877984:20666032598:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-3256872375598085327" 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" } } [18893:18893:0328/144235.878047:20666032657:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-3256872375598085327" [18893:18893:0328/144235.878091:20666032707:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [18893:18893:0328/144235.878146:20666032757:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [18893:18893:0328/144235.878188:20666032803:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000be0 with delay 1200000 [18893:18893:0328/144235.878240:20666032851:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [18893:18893:0328/144235.878386:20666033002:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [18893:18893:0328/144235.878446:20666033062:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424 [18893:18893:0328/144235.878500:20666033110:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f00 with delay 0 [18893:18893:0328/144235.878560:20666033173: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 [18893:18893:0328/144235.878613:20666033222:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f00 [18893:18893:0328/144235.878682:20666033291:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c00 with delay 0 [18893:18893:0328/144235.878729:20666033340:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424 [18893:18893:0328/144235.878778:20666033392:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e90 with delay 10000 [18893:18893:0328/144235.878830:20666033439:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c00 [18893:18893:0328/144235.878865:20666033486:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [18893:18893:0328/144235.878934:20666033545:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.879002:20666033617:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000c00 with delay 0 [18893:18893:0328/144235.879053:20666033664:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000c00 [18893:18893:0328/144235.879212:20666033823: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 } } [18893:18893:0328/144235.879303:20666033924: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 [18893:18893:0328/144235.879360:20666033971:INFO:protocol-handler.cc(294)] Adding subtree: { } [18893:18893:0328/144235.879406:20666034016:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 10376 with a delay 500000, Now = 211469424 [18893:18893:0328/144235.879449:20666034059:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f00 with delay 500 [18893:18893:0328/144235.879492:20666034102:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [18893:18893:0328/144235.879759:20666034371: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 } [18893:18893:0328/144235.879847:20666034463:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f00 [18893:18893:0328/144235.879907:20666034517:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.879989:20666034600:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.880032:20666034642:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [18893:18893:0328/144235.887773:20666042386: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 } } [18893:18893:0328/144235.888154:20666042764:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e90 [ OK ] InvalidationClientImplTest.ServerRequests (14 ms) [13/28] InvalidationClientImplTest.ServerRequests (14 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [18893:18893:0328/144235.889787:20666044398:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b30 with delay 0 [18893:18893:0328/144235.889860:20666044480:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [18893:18893:0328/144235.890137:20666044758:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000cf0 with delay 0 [18893:18893:0328/144235.890194:20666044807:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b30 [18893:18893:0328/144235.890235:20666044844:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000cf0 [18893:18893:0328/144235.890309:20666044920:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [18893:18893:0328/144235.890374:20666044984:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 0 [18893:18893:0328/144235.890425:20666045033:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ac0 [18893:18893:0328/144235.890459:20666045070:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [18893:18893:0328/144235.890500:20666045111:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000cf0 with delay 0 [18893:18893:0328/144235.890538:20666045147:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000cf0 [18893:18893:0328/144235.890572:20666045186:INFO:invalidation-client-core.cc(351)] Starting with no previous state [18893:18893:0328/144235.890617:20666045229:INFO:recurring-task.cc(55)] [Startup] Scheduling 9896 with a delay 0, Now = 210919424 [18893:18893:0328/144235.890658:20666045274:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 0 [18893:18893:0328/144235.890712:20666045321:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ac0 [18893:18893:0328/144235.890785:20666045395:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "185490947076651564" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [18893:18893:0328/144235.890838:20666045449:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9512 with a delay 500000, Now = 210919424 [18893:18893:0328/144235.890888:20666045504:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000cf0 with delay 500 [18893:18893:0328/144235.890936:20666045555:INFO:recurring-task.cc(55)] [Retry] Scheduling 9896 with a delay 60000000, Now = 210919424 [18893:18893:0328/144235.890986:20666045600:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ab0 with delay 60000 [18893:18893:0328/144235.891040:20666045650:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000cf0 [18893:18893:0328/144235.891081:20666045691:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.891132:20666045745:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.891277:20666045887: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: "185490947076651564" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [18893:18893:0328/144235.891396:20666046009:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000cf0 with delay 0 [18893:18893:0328/144235.891438:20666046049:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000cf0 [18893:18893:0328/144235.891570:20666046181:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "185490947076651564" 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" } } [18893:18893:0328/144235.891637:20666046254:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "185490947076651564" [18893:18893:0328/144235.891691:20666046301:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [18893:18893:0328/144235.891740:20666046350:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [18893:18893:0328/144235.891781:20666046391:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b10 with delay 1200000 [18893:18893:0328/144235.891832:20666046443:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [18893:18893:0328/144235.891967:20666046577:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [18893:18893:0328/144235.892010:20666046621:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [18893:18893:0328/144235.892051:20666046662:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ac0 with delay 0 [18893:18893:0328/144235.892110:20666046726: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 [18893:18893:0328/144235.892172:20666046782:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ac0 [18893:18893:0328/144235.892247:20666046856:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000009c0 with delay 0 [18893:18893:0328/144235.892292:20666046907:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [18893:18893:0328/144235.892336:20666046949:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b30 with delay 10000 [18893:18893:0328/144235.892376:20666046985:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000009c0 [18893:18893:0328/144235.892412:20666047029:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [18893:18893:0328/144235.892484:20666047094:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.892542:20666047153:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000009c0 with delay 0 [18893:18893:0328/144235.892584:20666047195:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000009c0 [18893:18893:0328/144235.892706:20666047327: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" } } [18893:18893:0328/144235.892812:20666047427: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 [18893:18893:0328/144235.892864:20666047488:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [18893:18893:0328/144235.893189:20666047800:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000b30 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (5 ms) [14/28] InvalidationClientImplTest.IncomingErrorMessage (5 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [18893:18893:0328/144235.894717:20666049328:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d70 with delay 0 [18893:18893:0328/144235.894781:20666049390:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [18893:18893:0328/144235.895119:20666049732:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0 [18893:18893:0328/144235.895168:20666049781:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d70 [18893:18893:0328/144235.895214:20666049823:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50 [18893:18893:0328/144235.895285:20666049895:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [18893:18893:0328/144235.895347:20666049957:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f30 with delay 0 [18893:18893:0328/144235.895393:20666050002:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f30 [18893:18893:0328/144235.895428:20666050038:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [18893:18893:0328/144235.895477:20666050088:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0 [18893:18893:0328/144235.895520:20666050129:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50 [18893:18893:0328/144235.895556:20666050170:INFO:invalidation-client-core.cc(351)] Starting with no previous state [18893:18893:0328/144235.895601:20666050221:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424 [18893:18893:0328/144235.895656:20666050272:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f30 with delay 0 [18893:18893:0328/144235.895706:20666050314:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f30 [18893:18893:0328/144235.895786:20666050396:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-3341769882868197149" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [18893:18893:0328/144235.895841:20666050451:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424 [18893:18893:0328/144235.895891:20666050502:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 500 [18893:18893:0328/144235.895936:20666050550:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424 [18893:18893:0328/144235.895984:20666050609:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c10 with delay 60000 [18893:18893:0328/144235.896059:20666050670:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50 [18893:18893:0328/144235.896108:20666050718:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.896159:20666050772:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.896299:20666050913: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: "-3341769882868197149" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [18893:18893:0328/144235.896438:20666051053:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e50 with delay 0 [18893:18893:0328/144235.896492:20666051106:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50 [18893:18893:0328/144235.896625:20666051238:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-3341769882868197149" 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" } } [18893:18893:0328/144235.896690:20666051300:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-3341769882868197149" [18893:18893:0328/144235.896738:20666051349:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [18893:18893:0328/144235.896793:20666051409:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [18893:18893:0328/144235.896846:20666051457:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 1200000 [18893:18893:0328/144235.896900:20666051517:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [18893:18893:0328/144235.897037:20666051647:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [18893:18893:0328/144235.897081:20666051697:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [18893:18893:0328/144235.897132:20666051742:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f30 with delay 0 [18893:18893:0328/144235.897192:20666051810: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 [18893:18893:0328/144235.897255:20666051864:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f30 [18893:18893:0328/144235.897332:20666051941:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 0 [18893:18893:0328/144235.897382:20666051993:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [18893:18893:0328/144235.897457:20666052075:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d70 with delay 10000 [18893:18893:0328/144235.897507:20666052116:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f40 [18893:18893:0328/144235.897541:20666052156:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [18893:18893:0328/144235.897605:20666052216:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f40 with delay 0 [18893:18893:0328/144235.897647:20666052258:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f40 [18893:18893:0328/144235.897707:20666052317:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [18893:18893:0328/144235.897771:20666052384:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9896 with a delay 500000, Now = 211469424 [18893:18893:0328/144235.897827:20666052437:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f30 with delay 500 [18893:18893:0328/144235.897891:20666052502:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9224 with a delay 60000000, Now = 211469424 [18893:18893:0328/144235.897934:20666052544:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f50 with delay 60000 [18893:18893:0328/144235.897992:20666052602:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f30 [18893:18893:0328/144235.898034:20666052645:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.898088:20666052708:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.898140:20666052753:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [18893:18893:0328/144235.898287:20666052900: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 } } } [18893:18893:0328/144235.898396:20666053006:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.898455:20666053067:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f30 with delay 0 [18893:18893:0328/144235.898501:20666053116:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f30 [18893:18893:0328/144235.898632:20666053242: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" } } [18893:18893:0328/144235.898708:20666053319: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 [18893:18893:0328/144235.898757:20666053368:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [18893:18893:0328/144235.898865:20666053486:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [18893:18893:0328/144235.899180:20666053794:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000d70 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms) [15/28] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [18893:18893:0328/144235.900709:20666055320:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c00 with delay 0 [18893:18893:0328/144235.900775:20666055384:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [18893:18893:0328/144235.901020:20666055634:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b30 with delay 0 [18893:18893:0328/144235.901067:20666055678:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c00 [18893:18893:0328/144235.901118:20666055726:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b30 [18893:18893:0328/144235.901185:20666055802:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [18893:18893:0328/144235.901255:20666055864:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e00 with delay 0 [18893:18893:0328/144235.901302:20666055913:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e00 [18893:18893:0328/144235.901340:20666055950:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [18893:18893:0328/144235.901388:20666055999:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b30 with delay 0 [18893:18893:0328/144235.901444:20666056053:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b30 [18893:18893:0328/144235.901479:20666056092:INFO:invalidation-client-core.cc(351)] Starting with no previous state [18893:18893:0328/144235.901524:20666056134:INFO:recurring-task.cc(55)] [Startup] Scheduling 9800 with a delay 0, Now = 210919424 [18893:18893:0328/144235.901579:20666056189:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e00 with delay 0 [18893:18893:0328/144235.901621:20666056230:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e00 [18893:18893:0328/144235.901694:20666056305:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "8195459694664952479" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [18893:18893:0328/144235.901749:20666056360:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9608 with a delay 500000, Now = 210919424 [18893:18893:0328/144235.901791:20666056409:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b30 with delay 500 [18893:18893:0328/144235.901837:20666056457:INFO:recurring-task.cc(55)] [Retry] Scheduling 9800 with a delay 60000000, Now = 210919424 [18893:18893:0328/144235.901902:20666056512:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 60000 [18893:18893:0328/144235.901954:20666056564:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b30 [18893:18893:0328/144235.901994:20666056604:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.902045:20666056661:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.902198:20666056808: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: "8195459694664952479" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [18893:18893:0328/144235.902317:20666056932:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b30 with delay 0 [18893:18893:0328/144235.902361:20666056971:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b30 [18893:18893:0328/144235.902494:20666057105:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "8195459694664952479" 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" } } [18893:18893:0328/144235.902558:20666057169:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "8195459694664952479" [18893:18893:0328/144235.902600:20666057216:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [18893:18893:0328/144235.902662:20666057272:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [18893:18893:0328/144235.902708:20666057318:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ec0 with delay 1200000 [18893:18893:0328/144235.902752:20666057362:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [18893:18893:0328/144235.902898:20666057509:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [18893:18893:0328/144235.902957:20666057568:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [18893:18893:0328/144235.903003:20666057613:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e00 with delay 0 [18893:18893:0328/144235.903063:20666057673: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 [18893:18893:0328/144235.903113:20666057723:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e00 [18893:18893:0328/144235.903185:20666057794:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a30 with delay 0 [18893:18893:0328/144235.903230:20666057843:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [18893:18893:0328/144235.903271:20666057890:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c00 with delay 10000 [18893:18893:0328/144235.903324:20666057932:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a30 [18893:18893:0328/144235.903359:20666057970:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [18893:18893:0328/144235.903423:20666058034:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a30 with delay 0 [18893:18893:0328/144235.903469:20666058085:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a30 [18893:18893:0328/144235.903533:20666058144:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [18893:18893:0328/144235.903598:20666058209:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9608 with a delay 500000, Now = 211469424 [18893:18893:0328/144235.903640:20666058251:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000e00 with delay 500 [18893:18893:0328/144235.903684:20666058294:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9416 with a delay 60000000, Now = 211469424 [18893:18893:0328/144235.903727:20666058338:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000ad0 with delay 60000 [18893:18893:0328/144235.903787:20666058397:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000e00 [18893:18893:0328/144235.903835:20666058446:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.903897:20666058508:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.903950:20666058560:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [18893:18893:0328/144235.904089:20666058706: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 } } } [18893:18893:0328/144235.904393:20666059010:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c00 [18893:18893:0328/144235.905606:20666060215:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000c30 [18893:18893:0328/144235.905654:20666060263:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x701000000ad0 [18893:18893:0328/144235.905714:20666060326: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 [18893:18893:0328/144235.905771:20666060381:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [18893:18893:0328/144235.905894:20666060504: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 } [18893:18893:0328/144235.905943:20666060553:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9608 with a delay 500000, Now = 271469424 [18893:18893:0328/144235.905987:20666060598:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c30 with delay 500 [18893:18893:0328/144235.906029:20666060640:INFO:recurring-task.cc(55)] [Retry] Scheduling 9416 with a delay 60000000, Now = 271469424 [18893:18893:0328/144235.906075:20666060689:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c00 with delay 60000 [18893:18893:0328/144235.906132:20666060742:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x701000000c30 [18893:18893:0328/144235.906173:20666060784:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.906234:20666060844:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.906274:20666060885:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [18893:18893:0328/144235.906434:20666061045: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 } } [ OK ] InvalidationClientImplTest.NetworkTimeouts (7 ms) [16/28] InvalidationClientImplTest.NetworkTimeouts (7 ms) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary [18893:18893:0328/144235.908238:20666062849:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e10 with delay 0 [18893:18893:0328/144235.908304:20666062916:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [18893:18893:0328/144235.908528:20666063146:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0 [18893:18893:0328/144235.908585:20666063196:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e10 [18893:18893:0328/144235.908627:20666063235:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0 [18893:18893:0328/144235.908695:20666063305:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [18893:18893:0328/144235.908763:20666063373:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 0 [18893:18893:0328/144235.908814:20666063423:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ad0 [18893:18893:0328/144235.908849:20666063462:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [18893:18893:0328/144235.908901:20666063511:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0 [18893:18893:0328/144235.908941:20666063550:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0 [18893:18893:0328/144235.908975:20666063585:INFO:invalidation-client-core.cc(351)] Starting with no previous state [18893:18893:0328/144235.909019:20666063629:INFO:recurring-task.cc(55)] [Startup] Scheduling 10376 with a delay 0, Now = 210919424 [18893:18893:0328/144235.909060:20666063671:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 0 [18893:18893:0328/144235.909104:20666063713:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ad0 [18893:18893:0328/144235.909175:20666063788:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-5249766688063280030" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [18893:18893:0328/144235.909219:20666063832:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9992 with a delay 500000, Now = 210919424 [18893:18893:0328/144235.909267:20666063886:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 500 [18893:18893:0328/144235.909319:20666063929:INFO:recurring-task.cc(55)] [Retry] Scheduling 10376 with a delay 60000000, Now = 210919424 [18893:18893:0328/144235.909360:20666063970:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000db0 with delay 60000 [18893:18893:0328/144235.909428:20666064038:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0 [18893:18893:0328/144235.909470:20666064081:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.909521:20666064132:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.909664:20666064275: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: "-5249766688063280030" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [18893:18893:0328/144235.909795:20666064412:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0 [18893:18893:0328/144235.909848:20666064459:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0 [18893:18893:0328/144235.909986:20666064602:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-5249766688063280030" 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" } } [18893:18893:0328/144235.910057:20666064668:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-5249766688063280030" [18893:18893:0328/144235.910101:20666064711:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [18893:18893:0328/144235.910147:20666064757:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424 [18893:18893:0328/144235.910186:20666064800:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e00 with delay 1200000 [18893:18893:0328/144235.910231:20666064845:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [18893:18893:0328/144235.910362:20666064972:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [18893:18893:0328/144235.910410:20666065020:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [18893:18893:0328/144235.910451:20666065061:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ad0 with delay 0 [18893:18893:0328/144235.910521:20666065131: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 [18893:18893:0328/144235.910570:20666065178:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ad0 [18893:18893:0328/144235.910640:20666065249:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a30 with delay 0 [18893:18893:0328/144235.910703:20666065314:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [18893:18893:0328/144235.910745:20666065355:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e10 with delay 10000 [18893:18893:0328/144235.910785:20666065393:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a30 [18893:18893:0328/144235.910825:20666065435:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [18893:18893:0328/144235.910895:20666065505:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.910961:20666065571:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a30 with delay 0 [18893:18893:0328/144235.911002:20666065611:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a30 [18893:18893:0328/144235.911094:20666065704: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" } } [18893:18893:0328/144235.911389:20666066000:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e10 [18893:18893:0328/144235.912382:20666066995: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" } } [ OK ] InvalidationClientImplTest.NoRegistrationSummary (5 ms) [17/28] InvalidationClientImplTest.NoRegistrationSummary (5 ms) [ RUN ] InvalidationClientImplTest.Heartbeats [18893:18893:0328/144235.912979:20666067590:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c70 with delay 0 [18893:18893:0328/144235.913044:20666067653:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [18893:18893:0328/144235.913267:20666067878:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0 [18893:18893:0328/144235.913313:20666067926:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c70 [18893:18893:0328/144235.913354:20666067963:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50 [18893:18893:0328/144235.913440:20666068050:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [18893:18893:0328/144235.913504:20666068113:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 0 [18893:18893:0328/144235.913550:20666068159:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ad0 [18893:18893:0328/144235.913585:20666068205:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [18893:18893:0328/144235.913643:20666068261:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0 [18893:18893:0328/144235.913693:20666068302:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50 [18893:18893:0328/144235.913731:20666068342:INFO:invalidation-client-core.cc(351)] Starting with no previous state [18893:18893:0328/144235.913774:20666068400:INFO:recurring-task.cc(55)] [Startup] Scheduling 9704 with a delay 0, Now = 210919424 [18893:18893:0328/144235.913832:20666068450:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 0 [18893:18893:0328/144235.913888:20666068497:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ad0 [18893:18893:0328/144235.913958:20666068569:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-4807652144819704118" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [18893:18893:0328/144235.914014:20666068624:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424 [18893:18893:0328/144235.914065:20666068694:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 500 [18893:18893:0328/144235.914128:20666068738:INFO:recurring-task.cc(55)] [Retry] Scheduling 9704 with a delay 60000000, Now = 210919424 [18893:18893:0328/144235.914166:20666068779:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000aa0 with delay 60000 [18893:18893:0328/144235.914218:20666068831:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50 [18893:18893:0328/144235.914258:20666068869:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.914314:20666068926:INFO:invalidation-client-core.cc(488)] Return client token = "" [18893:18893:0328/144235.914452:20666069066: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: "-4807652144819704118" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [18893:18893:0328/144235.914571:20666069181:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b50 with delay 0 [18893:18893:0328/144235.914615:20666069228:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50 [18893:18893:0328/144235.914748:20666069359:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-4807652144819704118" 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" } } [18893:18893:0328/144235.914813:20666069425:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-4807652144819704118" [18893:18893:0328/144235.914856:20666069475:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [18893:18893:0328/144235.914912:20666069530:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424 [18893:18893:0328/144235.914970:20666069580:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a30 with delay 1200000 [18893:18893:0328/144235.915017:20666069628:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [18893:18893:0328/144235.915141:20666069755:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [18893:18893:0328/144235.915185:20666069795:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [18893:18893:0328/144235.915233:20666069844:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ad0 with delay 0 [18893:18893:0328/144235.915296:20666069918: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 [18893:18893:0328/144235.915358:20666069968:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ad0 [18893:18893:0328/144235.915427:20666070036:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0 [18893:18893:0328/144235.915480:20666070097:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [18893:18893:0328/144235.915531:20666070141:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c70 with delay 10000 [18893:18893:0328/144235.915568:20666070177:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0 [18893:18893:0328/144235.915602:20666070219:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [18893:18893:0328/144235.915939:20666070550:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c70 [18893:18893:0328/144235.917101:20666071710:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000aa0 [18893:18893:0328/144235.943158:20666097771:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x701000000a30 [18893:18893:0328/144235.943233:20666097849:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [18893:18893:0328/144235.943303:20666097929:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [18893:18893:0328/144235.943364:20666097981:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [18893:18893:0328/144235.943593:20666098204: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 } [18893:18893:0328/144235.943655:20666098267:INFO:recurring-task.cc(55)] [Send-info] Scheduling 10376 with a delay 500000, Now = 1411419424 [18893:18893:0328/144235.943710:20666098320:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000aa0 with delay 500 [18893:18893:0328/144235.943753:20666098367:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424 [18893:18893:0328/144235.943796:20666098422:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000c70 with delay 1200000 [18893:18893:0328/144235.943862:20666098479:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x701000000aa0 [18893:18893:0328/144235.943908:20666098519:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.943990:20666098600:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [18893:18893:0328/144235.944028:20666098643:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [18893:18893:0328/144235.944287:20666098906: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 } } [ OK ] InvalidationClientImplTest.Heartbeats (33 ms) [18/28] InvalidationClientImplTest.Heartbeats (33 ms) [ RUN ] ProtocolHandlerTest.SendInitializeOnly [18895:18895:0328/144235.865625:20666020243:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b60 with delay 0 [18895:18895:0328/144235.865964:20666020574:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b60 [18895:18895:0328/144235.866294:20666020903: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 } [18895:18895:0328/144235.866364:20666020973:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 500000, Now = 210919424 [18895:18895:0328/144235.866404:20666021013:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000bf0 with delay 500 [18895:18895:0328/144235.866452:20666021063:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000bf0 [18895:18895:0328/144235.866711:20666021320: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 } } [ OK ] ProtocolHandlerTest.SendInitializeOnly (2 ms) [19/28] ProtocolHandlerTest.SendInitializeOnly (2 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [18895:18895:0328/144235.867800:20666022410: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" } } [ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (0 ms) [20/28] ProtocolHandlerTest.ReceiveTokenControlOnly (0 ms) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes [18895:18895:0328/144235.868253:20666022867:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0 [18895:18895:0328/144235.868321:20666022939:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b20 with delay 0 [18895:18895:0328/144235.868376:20666022989:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000aa0 with delay 0 [18895:18895:0328/144235.868440:20666023049:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ae0 with delay 0 [18895:18895:0328/144235.868478:20666023086:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a90 with delay 0 [18895:18895:0328/144235.868517:20666023126:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 0 [18895:18895:0328/144235.868867:20666023487:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0 [18895:18895:0328/144235.869011:20666023624: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 } [18895:18895:0328/144235.869070:20666023680:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9320 with a delay 500000, Now = 210919424 [18895:18895:0328/144235.869118:20666023727:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c40 with delay 500 [18895:18895:0328/144235.869158:20666023766:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b20 [18895:18895:0328/144235.869199:20666023807:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000aa0 [18895:18895:0328/144235.869234:20666023842:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ae0 [18895:18895:0328/144235.869269:20666023877:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000a90 [18895:18895:0328/144235.869320:20666023928:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ad0 [18895:18895:0328/144235.869376:20666023985:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [18895:18895:0328/144235.869464:20666024080:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c40 [18895:18895:0328/144235.869626:20666024238:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [18895:18895:0328/144235.870880:20666025502: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 } } [ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (3 ms) [21/28] ProtocolHandlerTest.SendMultipleMessageTypes (3 ms) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage [18895:18895:0328/144235.872470:20666027080: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 } } [ OK ] ProtocolHandlerTest.IncomingCompositeMessage (1 ms) [22/28] ProtocolHandlerTest.IncomingCompositeMessage (1 ms) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage [18895:18895:0328/144235.873052:20666027665: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 } } [18895:18895:0328/144235.873145:20666027754: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" } [18895:18895:0328/144235.873230:20666027839: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 } } [18895:18895:0328/144235.873331:20666027940: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 } } [ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms) [23/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch [18895:18895:0328/144235.873796:20666028404: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 } } [18895:18895:0328/144235.873912:20666028520: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 } } [ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms) [24/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch [18895:18895:0328/144235.874320:20666028929: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" } } [ OK ] ProtocolHandlerTest.MinorVersionMismatch (0 ms) [25/28] ProtocolHandlerTest.MinorVersionMismatch (0 ms) [ RUN ] ProtocolHandlerTest.ConfigMessage [18895:18895:0328/144235.874744:20666029354: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" } } [18895:18895:0328/144235.874807:20666029415:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a20 with delay 0 [18895:18895:0328/144235.874840:20666029449:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000a20 [18895:18895:0328/144235.874923:20666029532: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 } [18895:18895:0328/144235.874972:20666029580:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9704 with a delay 500000, Now = 210919424 [18895:18895:0328/144235.875007:20666029615:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a30 with delay 500 [18895:18895:0328/144235.875052:20666029660:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a30 [18895:18895:0328/144235.875087:20666029700:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 [ OK ] ProtocolHandlerTest.ConfigMessage (44 ms) [26/28] ProtocolHandlerTest.ConfigMessage (44 ms) [ RUN ] ProtocolHandlerTest.ErrorMessage [18895:18895:0328/144235.918502:20666073113: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" } } [ OK ] ProtocolHandlerTest.ErrorMessage (0 ms) [27/28] ProtocolHandlerTest.ErrorMessage (0 ms) [ RUN ] ProtocolHandlerTest.TokenMismatch [18895:18895:0328/144235.919004:20666073615: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" } } [ OK ] ProtocolHandlerTest.TokenMismatch (1 ms) [28/28] ProtocolHandlerTest.TokenMismatch (1 ms) SUCCESS: all tests passed. Tests took 0 seconds. 2019-03-28 15:31:16,013 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmpvPSR0l/43df3d6feaf09f10'] 2019-03-28 15:31:16,013 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmpvPSR0l/43df3d6feaf09f10/output.json'] 2019-03-28 15:31:16,014 - root: [INFO] merge_cmd: /b/swarming/w/ir/cache/vpython/ba947a/bin/python /b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --build-properties {"blamelist": ["pcc@chromium.org"], "bot_id": "swarm1906-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:pcc@google.com", "created_ts": 1553807815101901, "id": "8917708132430700752", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1411", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1534187/4", "user_agent:git_cl_try"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1411, "category": "git_cl_try", "got_angle_revision": "2e5afde1d68b68ab543e508c311c94f09921c07c", "got_dawn_revision": "19179e180b2e04990a725b038782e40b80fa75f3", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "8f3cd84f6cadd65279873b6834e843778ff9976a", "got_revision_cp": "refs/heads/master@{#645503}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "370905e268aed09b47e08d593d95f4f31f79cfc6", "got_v8_revision_cp": "refs/heads/7.5.138@{#1}", "got_webrtc_revision": "4c7112a27a535990ed7d7a6d990391ca7ffdc3eb", "got_webrtc_revision_cp": "refs/heads/master@{#27348}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1534187, "patch_project": "chromium/src", "patch_ref": "refs/changes/87/1534187/4", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 4, "patch_storage": "gerrit", "path_config": "generic", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src"} --summary-json /b/swarming/w/ir/tmp/t/tmp6Yyp4b.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpvPSR0l -o /b/swarming/w/ir/tmp/t/tmp3ywz1X.json /b/swarming/w/ir/tmp/t/tmpvPSR0l/43df3d6feaf09f10/output.json Running ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"blamelist": ["pcc@chromium.org"], "bot_id": "swarm1906-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:pcc@google.com", "created_ts": 1553807815101901, "id": "8917708132430700752", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1411", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1534187/4", "user_agent:git_cl_try"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1411, "category": "git_cl_try", "got_angle_revision": "2e5afde1d68b68ab543e508c311c94f09921c07c", "got_dawn_revision": "19179e180b2e04990a725b038782e40b80fa75f3", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "8f3cd84f6cadd65279873b6834e843778ff9976a", "got_revision_cp": "refs/heads/master@{#645503}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "370905e268aed09b47e08d593d95f4f31f79cfc6", "got_v8_revision_cp": "refs/heads/7.5.138@{#1}", "got_webrtc_revision": "4c7112a27a535990ed7d7a6d990391ca7ffdc3eb", "got_webrtc_revision_cp": "refs/heads/master@{#27348}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1534187, "patch_project": "chromium/src", "patch_ref": "refs/changes/87/1534187/4", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 4, "patch_storage": "gerrit", "path_config": "generic", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src"}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp6Yyp4b.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpvPSR0l', '-o', '/b/swarming/w/ir/tmp/t/tmp3ywz1X.json', '/b/swarming/w/ir/tmp/t/tmpvPSR0l/43df3d6feaf09f10/output.json'] in None (env: None) Command ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"blamelist": ["pcc@chromium.org"], "bot_id": "swarm1906-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:pcc@google.com", "created_ts": 1553807815101901, "id": "8917708132430700752", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1411", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1534187/4", "user_agent:git_cl_try"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1411, "category": "git_cl_try", "got_angle_revision": "2e5afde1d68b68ab543e508c311c94f09921c07c", "got_dawn_revision": "19179e180b2e04990a725b038782e40b80fa75f3", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "8f3cd84f6cadd65279873b6834e843778ff9976a", "got_revision_cp": "refs/heads/master@{#645503}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "370905e268aed09b47e08d593d95f4f31f79cfc6", "got_v8_revision_cp": "refs/heads/7.5.138@{#1}", "got_webrtc_revision": "4c7112a27a535990ed7d7a6d990391ca7ffdc3eb", "got_webrtc_revision_cp": "refs/heads/master@{#27348}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1534187, "patch_project": "chromium/src", "patch_ref": "refs/changes/87/1534187/4", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 4, "patch_storage": "gerrit", "path_config": "generic", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src"}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp6Yyp4b.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpvPSR0l', '-o', '/b/swarming/w/ir/tmp/t/tmp3ywz1X.json', '/b/swarming/w/ir/tmp/t/tmpvPSR0l/43df3d6feaf09f10/output.json'] returned exit code 0