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/tmpmnIpT_.json --task-output-dir /b/swarming/w/ir/tmp/t/tmp1HVDu8 --merge-script /b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/standard_gtest_merge.py --merge-script-stdout-file /b/swarming/w/ir/tmp/t/tmptkh64hmerge_script_log --merge-additional-args '[]' --build-properties '{"attempt_start_ts": 1551814694000000, "blamelist": ["bungeman@chromium.org"], "bot_id": "swarm1908-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:5071639625-1lppvbtck1morgivc6sq4dul7klu27sd@developer.gserviceaccount.com", "created_ts": 1551814721480501, "id": "8919798042567208160", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1394", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1504002/1", "cq_experimental:false", "user_agent:cq"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1394, "category": "cq", "got_angle_revision": "f094bac949922dabc3dd6944f3dec04111e953b6", "got_dawn_revision": "b47470daa7377a804df5d94e7a93b5925a57f84a", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "79d7f822d09d101a0ed5ae719b2d62f750c4cad2", "got_revision_cp": "refs/heads/master@{#637770}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "6641700a356c9a321198ea8beefcd9323a4da862", "got_v8_revision_cp": "refs/heads/7.4.282@{#1}", "got_webrtc_revision": "7949f215c1183d8bfc5b13f86594a03d3d648f68", "got_webrtc_revision_cp": "refs/heads/master@{#26971}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1504002, "patch_project": "chromium/src", "patch_ref": "refs/changes/02/1504002/1", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 1, "patch_storage": "gerrit", "path_config": "generic", "reason": "CQ", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src", "revision": "HEAD"}' --summary-json-file /b/swarming/w/ir/tmp/t/tmp3rtNCY.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/tmpCdnmlT.json in dir /b/swarming/w/ir/k: allow_subannotations: True base_name: 'cacheinvalidation_unittests (with patch)' 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/tmpmnIpT_.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmp1HVDu8', '--merge-script', '/b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/standard_gtest_merge.py', '--merge-script-stdout-file', '/b/swarming/w/ir/tmp/t/tmptkh64hmerge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"attempt_start_ts": 1551814694000000, "blamelist": ["bungeman@chromium.org"], "bot_id": "swarm1908-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:5071639625-1lppvbtck1morgivc6sq4dul7klu27sd@developer.gserviceaccount.com", "created_ts": 1551814721480501, "id": "8919798042567208160", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1394", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1504002/1", "cq_experimental:false", "user_agent:cq"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1394, "category": "cq", "got_angle_revision": "f094bac949922dabc3dd6944f3dec04111e953b6", "got_dawn_revision": "b47470daa7377a804df5d94e7a93b5925a57f84a", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "79d7f822d09d101a0ed5ae719b2d62f750c4cad2", "got_revision_cp": "refs/heads/master@{#637770}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "6641700a356c9a321198ea8beefcd9323a4da862", "got_v8_revision_cp": "refs/heads/7.4.282@{#1}", "got_webrtc_revision": "7949f215c1183d8bfc5b13f86594a03d3d648f68", "got_webrtc_revision_cp": "refs/heads/master@{#26971}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1504002, "patch_project": "chromium/src", "patch_ref": "refs/changes/02/1504002/1", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 1, "patch_storage": "gerrit", "path_config": "generic", "reason": "CQ", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src", "revision": "HEAD"}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmp3rtNCY.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/tmpCdnmlT.json'] env: {'CHROME_HEADLESS': '1'} env_prefixes: {'PATH': '/b/swarming/w/ir/cache/swarming_client'} env_suffixes: {} infra_step: False name: 'cacheinvalidation_unittests (with patch)' nest_level: 0 ok_ret: frozenset([0]) step_test_data: <lambda>(...) trigger_specs: () full environment: ADDRFAM: inet BOTO_CONFIG: /b/swarming/w/ir/tmp/gsutil_task/.boto BUILDBUCKET_EXPERIMENTAL: FALSE CHROME_HEADLESS: 1 CIPD_CACHE_DIR: /b/swarming/cipd_cache/cache CIPD_PROTOCOL: v2 DEVSHELL_CLIENT_PORT: 36796 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/8919798042567208160 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/itBhv6JC/luci_context.103234713 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: swarm1908-c4 SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 43682f11fbc64011 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-05 12:29:45,941 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmp1HVDu8' 2019-03-05 12:29:45,941 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmp1HVDu8' already exists! 2019-03-05 12:29:45,941 - root: [WARNING] task_output_dir existing content: [] 2019-03-05 12:29:45,942 - 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/tmpCdnmlT.json -output-dir /b/swarming/w/ir/tmp/t/tmp1HVDu8 -task-summary-json /b/swarming/w/ir/tmp/t/tmp3rtNCY.json [D2019-03-05T12:29:45.947438-08:00 16420 0 auth.go:1265] Minting a new token {"key":"luci_ctx/88a76f95de46254ad2a42dca5417a8164cdee92d9941da417302563b81309ee8", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-05T12:29:45.947589-08:00 16420 0 luci_ctx.go:138] POST http://127.0.0.1:42864/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/88a76f95de46254ad2a42dca5417a8164cdee92d9941da417302563b81309ee8", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-05T12:29:45.949296-08:00 16420 0 auth.go:1222] Token expires in 38m45.050724634s {"key":"luci_ctx/88a76f95de46254ad2a42dca5417a8164cdee92d9941da417302563b81309ee8", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 43685b6db6321910: 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 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/ioeP3dRZ/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 [13311:13311:0305/122720.826309:1089264576:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 0 [13311:13311:0305/122720.826396:1089264657:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b80 [13311:13311:0305/122720.826790:1089265050: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 } [13311:13311:0305/122720.826852:1089265112:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9224 with a delay 500000, Now = 210919424 [13311:13311:0305/122720.826896:1089265155:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b90 with delay 500 [13311:13311:0305/122720.826950:1089265215:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b90 [13311:13311:0305/122720.827077:1089265337:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [13311:13311:0305/122720.827119:1089265379:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (2 ms) [1/28] ProtocolHandlerTest.TokenMissing (2 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [13311:13311:0305/122720.827644:1089265907:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b90 with delay 0 [13311:13311:0305/122720.827703:1089265963:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b90 [13311:13311:0305/122720.827756:1089266016:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9320 with a delay 500000, Now = 210919424 [13311:13311:0305/122720.827797:1089266057:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 500 [13311:13311:0305/122720.827852:1089266112:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b80 [13311:13311:0305/122720.827961:1089266221:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [13311:13311:0305/122720.828058:1089266321: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 } [13311:13311:0305/122720.828133:1089266392: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 } } [13311:13311:0305/122720.828294:1089266555: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 } } } [13311:13311:0305/122720.828441:1089266701: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 [13311:13311:0305/122720.828938:1089267204:INFO:protocol-handler.cc(139)] Incoming message: { } [13311:13311:0305/122720.829010:1089267276:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [13311:13311:0305/122720.829059:1089267321:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [3/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [ RUN ] RecurringTaskTest.PeriodicTask [13311:13311:0305/122720.829350:1089267610:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 679714712 with a delay 10000, Now = 0 [13311:13311:0305/122720.829394:1089267654:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009f0 with delay 10 [13311:13311:0305/122720.829444:1089267704:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009f0 [13311:13311:0305/122720.829482:1089267750:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [13311:13311:0305/122720.829538:1089267798:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 10000 [13311:13311:0305/122720.829587:1089267848:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000000a00 with delay 60 [13311:13311:0305/122720.829630:1089267889:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x701000000a00 [13311:13311:0305/122720.829664:1089267923:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [13311:13311:0305/122720.829700:1089267958:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 70000 [13311:13311:0305/122720.829733:1089267992:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7010000009f0 with delay 60 [13311:13311:0305/122720.829802:1089268060:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7010000009f0 [13311:13311:0305/122720.829835:1089268093:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [13311:13311:0305/122720.829868:1089268126:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 130000 [13311:13311:0305/122720.829902:1089268160:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x701000000a00 with delay 60 [13311:13311:0305/122720.829936:1089268195:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x701000000a00 [13311:13311:0305/122720.829969:1089268228:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [13311:13311:0305/122720.830014:1089268273:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 190000 [13311:13311:0305/122720.830047:1089268306:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7010000009f0 with delay 60 [13311:13311:0305/122720.830083:1089268341:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7010000009f0 [13311:13311:0305/122720.830115:1089268374:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [13311:13311:0305/122720.830148:1089268406:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 250000 [13311:13311:0305/122720.830180:1089268443:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x701000000a00 with delay 60 [13311:13311:0305/122720.830219:1089268478:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x701000000a00 [13311:13311:0305/122720.830251:1089268510:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [13311:13311:0305/122720.830284:1089268542:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 310000 [13311:13311:0305/122720.830317:1089268576:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7010000009f0 with delay 60 [13311:13311:0305/122720.830352:1089268610:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7010000009f0 [13311:13311:0305/122720.830384:1089268643:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [13311:13311:0305/122720.830423:1089268682:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714712 with a delay 60000, Now = 370000 [13311:13311:0305/122720.830456:1089268715:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x701000000a00 with delay 60 [13311:13311:0305/122720.830492:1089268751:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x701000000a00 [13311:13311:0305/122720.830529:1089268789:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (2 ms) [4/28] RecurringTaskTest.PeriodicTask (2 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [13311:13311:0305/122720.831779:1089270045:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 679714528 with a delay 10000, Now = 0 [13311:13311:0305/122720.831835:1089270095:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000000a00 with delay 10 [13311:13311:0305/122720.831879:1089270138:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000000a00 [13311:13311:0305/122720.831919:1089270183:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [13311:13311:0305/122720.831985:1089270254:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 50000, Now = 10000 [13311:13311:0305/122720.832036:1089270295:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 50 [13311:13311:0305/122720.832077:1089270336:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7010000009f0 [13311:13311:0305/122720.832115:1089270375:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [13311:13311:0305/122720.832164:1089270424:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 149000, Now = 60000 [13311:13311:0305/122720.832212:1089270472:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x701000000a00 with delay 149 [13311:13311:0305/122720.832256:1089270516:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x701000000a00 [13311:13311:0305/122720.832295:1089270554:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [13311:13311:0305/122720.832332:1089270594:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 248000, Now = 210000 [13311:13311:0305/122720.832372:1089270634:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7010000009f0 with delay 248 [13311:13311:0305/122720.832417:1089270676:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7010000009f0 [13311:13311:0305/122720.832456:1089270715:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [13311:13311:0305/122720.832495:1089270755:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 446000, Now = 460000 [13311:13311:0305/122720.832536:1089270796:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x701000000a00 with delay 446 [13311:13311:0305/122720.832584:1089270851:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x701000000a00 [13311:13311:0305/122720.832632:1089270892:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [13311:13311:0305/122720.832672:1089270932:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 842000, Now = 910000 [13311:13311:0305/122720.832713:1089270973:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7010000009f0 with delay 842 [13311:13311:0305/122720.832769:1089271027:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7010000009f0 [13311:13311:0305/122720.832802:1089271060:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [13311:13311:0305/122720.832835:1089271093:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 1040000, Now = 1760000 [13311:13311:0305/122720.832868:1089271126:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x701000000a00 with delay 1040 [13311:13311:0305/122720.832925:1089271183:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x701000000a00 [13311:13311:0305/122720.832957:1089271216:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [13311:13311:0305/122720.833005:1089271263:INFO:recurring-task.cc(55)] [Retry] Scheduling 679714528 with a delay 1040000, Now = 2800000 [13311:13311:0305/122720.833038:1089271297:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7010000009f0 with delay 1040 [13311:13311:0305/122720.833095:1089271353:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7010000009f0 [13311:13311:0305/122720.833127:1089271388:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms) [5/28] RecurringTaskTest.ExponentialBackoffTask (3 ms) [ RUN ] RecurringTaskTest.OneShotTask [13311:13311:0305/122720.834319:1089272579:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 679714568 with a delay 10000, Now = 0 [13311:13311:0305/122720.834367:1089272626:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009f0 with delay 10 [13311:13311:0305/122720.834409:1089272668:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009f0 [13311:13311:0305/122720.834445:1089272705:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [13311:13311:0305/122720.834486:1089272746:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 679714568 with a delay 10000, Now = 10000 [13311:13311:0305/122720.834530:1089272790:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 10 [13311:13311:0305/122720.834570:1089272829:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7010000009f0 [13311:13311:0305/122720.834606:1089272869:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (1 ms) [6/28] RecurringTaskTest.OneShotTask (1 ms) [ RUN ] ThrottleTest.ThrottlingScripted [13311:13311:0305/122720.835877:1089274137:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7010000009f0 with delay 920 [13311:13311:0305/122720.835942:1089274201:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009f0 [13311:13311:0305/122720.836303:1089274569:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7010000009f0 with delay 45000 [13311:13311:0305/122720.837463:1089275727:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000009f0 [ OK ] ThrottleTest.ThrottlingScripted (2 ms) [7/28] ThrottleTest.ThrottlingScripted (2 ms) [ RUN ] ThrottleTest.ThrottlingStorm [13311:13311:0305/122720.837630:1089275890:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 990 [13311:13311:0305/122720.837717:1089275977:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009f0 [13311:13311:0305/122720.837794:1089276053:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.837859:1089276117:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7010000009f0 [13311:13311:0305/122720.837894:1089276152:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.837955:1089276212:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7010000009f0 [13311:13311:0305/122720.837999:1089276257:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.838061:1089276319:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7010000009f0 [13311:13311:0305/122720.838095:1089276352:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.838155:1089276413:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7010000009f0 [13311:13311:0305/122720.838193:1089276452:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.838254:1089276512:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7010000009f0 [13311:13311:0305/122720.838292:1089276552:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x701000000a00 with delay 54000 [13311:13311:0305/122720.839905:1089278164:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x701000000a00 [13311:13311:0305/122720.839949:1089278207:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x701000000a00 with delay 1000 [13311:13311:0305/122720.840020:1089278278:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x701000000a00 [13311:13311:0305/122720.840055:1089278313:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x701000000a00 with delay 1000 [13311:13311:0305/122720.840115:1089278373:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x701000000a00 [13311:13311:0305/122720.840149:1089278407:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x701000000a00 with delay 1000 [13311:13311:0305/122720.840215:1089278472:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x701000000a00 [13311:13311:0305/122720.840249:1089278507:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x701000000a00 with delay 1000 [13311:13311:0305/122720.840309:1089278567:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x701000000a00 [13311:13311:0305/122720.840343:1089278601:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x701000000a00 with delay 1000 [13311:13311:0305/122720.840403:1089278661:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x701000000a00 [13311:13311:0305/122720.840437:1089278695:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x701000000a00 with delay 1000 [13311:13311:0305/122720.840503:1089278761:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x701000000a00 [13311:13311:0305/122720.840537:1089278795:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7010000009f0 with delay 54000 [13311:13311:0305/122720.842164:1089280422:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7010000009f0 [13311:13311:0305/122720.842206:1089280464:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.842267:1089280525:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7010000009f0 [13311:13311:0305/122720.842301:1089280559:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.842362:1089280619:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7010000009f0 [13311:13311:0305/122720.842395:1089280653:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.842456:1089280713:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7010000009f0 [13311:13311:0305/122720.842489:1089280747:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.842549:1089280807:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7010000009f0 [13311:13311:0305/122720.842583:1089280841:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.842643:1089280901:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7010000009f0 [13311:13311:0305/122720.842677:1089280937:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.842739:1089280997:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7010000009f0 [13311:13311:0305/122720.842773:1089281031:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x701000000a00 with delay 54000 [13311:13311:0305/122720.844406:1089282664:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x701000000a00 [13311:13311:0305/122720.844445:1089282703:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x701000000a00 with delay 1000 [13311:13311:0305/122720.844505:1089282763:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x701000000a00 [13311:13311:0305/122720.844539:1089282797:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x701000000a00 with delay 1000 [13311:13311:0305/122720.844605:1089282863:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x701000000a00 [13311:13311:0305/122720.844639:1089282897:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x701000000a00 with delay 1000 [13311:13311:0305/122720.844701:1089282959:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x701000000a00 [13311:13311:0305/122720.844735:1089282995:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x701000000a00 with delay 1000 [13311:13311:0305/122720.844798:1089283055:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x701000000a00 [13311:13311:0305/122720.844831:1089283089:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x701000000a00 with delay 1000 [13311:13311:0305/122720.844891:1089283149:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x701000000a00 [13311:13311:0305/122720.844925:1089283183:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x701000000a00 with delay 1000 [13311:13311:0305/122720.844986:1089283253:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x701000000a00 [13311:13311:0305/122720.845029:1089283288:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7010000009f0 with delay 54000 [13311:13311:0305/122720.846640:1089284898:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7010000009f0 [13311:13311:0305/122720.846683:1089284943:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.846746:1089285004:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7010000009f0 [13311:13311:0305/122720.846780:1089285038:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.846841:1089285098:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7010000009f0 [13311:13311:0305/122720.846874:1089285132:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.846935:1089285192:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7010000009f0 [13311:13311:0305/122720.846968:1089285226:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.847039:1089285297:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7010000009f0 [13311:13311:0305/122720.847073:1089285331:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.847133:1089285391:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7010000009f0 [13311:13311:0305/122720.847167:1089285425:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7010000009f0 with delay 1000 [13311:13311:0305/122720.847232:1089285492:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7010000009f0 [13311:13311:0305/122720.847267:1089285526:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x701000000a00 with delay 54000 [13311:13311:0305/122720.848886:1089287144:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x701000000a00 [ OK ] ThrottleTest.ThrottlingStorm (11 ms) [8/28] ThrottleTest.ThrottlingStorm (11 ms) [ RUN ] ProtocolHandlerTest.SendInitializeOnly [13310:13310:0305/122720.800304:1089238567:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 0 [13310:13310:0305/122720.800660:1089238933:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b80 [13310:13310:0305/122720.801067:1089239327: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 } [13310:13310:0305/122720.801141:1089239415:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 500000, Now = 210919424 [13310:13310:0305/122720.801199:1089239472:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c10 with delay 500 [13310:13310:0305/122720.801273:1089239533:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c10 [13310:13310:0305/122720.801579:1089239839: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 (3 ms) [9/28] ProtocolHandlerTest.SendInitializeOnly (3 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [13310:13310:0305/122720.802809:1089241076: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 (1 ms) [10/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes [13310:13310:0305/122720.803320:1089241580:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0 [13310:13310:0305/122720.803408:1089241671:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b40 with delay 0 [13310:13310:0305/122720.803456:1089241718:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 0 [13310:13310:0305/122720.803524:1089241783:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b00 with delay 0 [13310:13310:0305/122720.803561:1089241819:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ab0 with delay 0 [13310:13310:0305/122720.803617:1089241889:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0 [13310:13310:0305/122720.804013:1089242273:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10 [13310:13310:0305/122720.804161:1089242427: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 } [13310:13310:0305/122720.804234:1089242495:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9320 with a delay 500000, Now = 210919424 [13310:13310:0305/122720.804280:1089242539:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c60 with delay 500 [13310:13310:0305/122720.804329:1089242588:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b40 [13310:13310:0305/122720.804381:1089242639:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ac0 [13310:13310:0305/122720.804420:1089242678:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b00 [13310:13310:0305/122720.804458:1089242715:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ab0 [13310:13310:0305/122720.804495:1089242752:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0 [13310:13310:0305/122720.804553:1089242812:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [13310:13310:0305/122720.804612:1089242871:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c60 [13310:13310:0305/122720.804772:1089243037:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [13310:13310:0305/122720.806503:1089244771: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 (4 ms) [11/28] ProtocolHandlerTest.SendMultipleMessageTypes (4 ms) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage [13310:13310:0305/122720.808300:1089246568: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) [12/28] ProtocolHandlerTest.IncomingCompositeMessage (1 ms) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage [13310:13310:0305/122720.808982:1089247256: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 } } [13310:13310:0305/122720.809083:1089247343: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" } [13310:13310:0305/122720.809195:1089247457: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 } } [13310:13310:0305/122720.809297:1089247559: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) [13/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch [13310:13310:0305/122720.809832:1089248100: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 } } [13310:13310:0305/122720.809967:1089248232: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) [14/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch [13310:13310:0305/122720.810493:1089248753: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) [15/28] ProtocolHandlerTest.MinorVersionMismatch (0 ms) [ RUN ] ProtocolHandlerTest.ConfigMessage [13310:13310:0305/122720.811054:1089249314: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" } } [13310:13310:0305/122720.811121:1089249389:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a40 with delay 0 [13310:13310:0305/122720.811171:1089249430:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000a40 [13310:13310:0305/122720.811264:1089249529: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 } [13310:13310:0305/122720.811334:1089249594:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9704 with a delay 500000, Now = 210919424 [13310:13310:0305/122720.811381:1089249647:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a50 with delay 500 [13310:13310:0305/122720.811449:1089249715:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50 [13310:13310:0305/122720.811503:1089249767:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 [ OK ] ProtocolHandlerTest.ConfigMessage (45 ms) [16/28] ProtocolHandlerTest.ConfigMessage (45 ms) [ RUN ] ProtocolHandlerTest.ErrorMessage [13310:13310:0305/122720.856060:1089294321: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 (1 ms) [17/28] ProtocolHandlerTest.ErrorMessage (1 ms) [ RUN ] ProtocolHandlerTest.TokenMismatch [13310:13310:0305/122720.856627:1089294894: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 (0 ms) [18/28] ProtocolHandlerTest.TokenMismatch (0 ms) [ RUN ] InvalidationClientImplTest.Start [13307:13307:0305/122720.774677:1089212942:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c80 with delay 0 [13307:13307:0305/122720.775053:1089213314:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13307:13307:0305/122720.775360:1089213621:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0 [13307:13307:0305/122720.775407:1089213667:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c80 [13307:13307:0305/122720.775446:1089213704:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50 [13307:13307:0305/122720.775531:1089213791:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13307:13307:0305/122720.775618:1089213880:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ea0 with delay 0 [13307:13307:0305/122720.775671:1089213929:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ea0 [13307:13307:0305/122720.775706:1089213970:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13307:13307:0305/122720.775749:1089214009:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0 [13307:13307:0305/122720.775789:1089214047:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50 [13307:13307:0305/122720.775836:1089214095:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13307:13307:0305/122720.775884:1089214144:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 0, Now = 210919424 [13307:13307:0305/122720.775924:1089214183:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ea0 with delay 0 [13307:13307:0305/122720.775961:1089214219:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ea0 [13307:13307:0305/122720.776062:1089214324:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "4870639173317762515" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13307:13307:0305/122720.776118:1089214377:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9416 with a delay 500000, Now = 210919424 [13307:13307:0305/122720.776157:1089214416:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 500 [13307:13307:0305/122720.776196:1089214455:INFO:recurring-task.cc(55)] [Retry] Scheduling 9224 with a delay 60000000, Now = 210919424 [13307:13307:0305/122720.776235:1089214494:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e10 with delay 60000 [13307:13307:0305/122720.776284:1089214545:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50 [13307:13307:0305/122720.776331:1089214590:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.776400:1089214659:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.776597:1089214859: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: "4870639173317762515" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13307:13307:0305/122720.776791:1089215055:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e50 with delay 0 [13307:13307:0305/122720.776839:1089215098:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50 [13307:13307:0305/122720.776986:1089215263:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "4870639173317762515" 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" } } [13307:13307:0305/122720.777075:1089215334:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "4870639173317762515" [13307:13307:0305/122720.777124:1089215384:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13307:13307:0305/122720.777169:1089215429:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [13307:13307:0305/122720.777207:1089215469:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e90 with delay 1200000 [13307:13307:0305/122720.777251:1089215514:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13307:13307:0305/122720.777425:1089215685:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13307:13307:0305/122720.777468:1089215729:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424 [13307:13307:0305/122720.777507:1089215767:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ea0 with delay 0 [13307:13307:0305/122720.777586:1089215849: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 [13307:13307:0305/122720.777643:1089215902:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ea0 [13307:13307:0305/122720.777728:1089215992:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ec0 with delay 0 [13307:13307:0305/122720.777808:1089216067:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424 [13307:13307:0305/122720.777853:1089216112:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c80 with delay 10000 [13307:13307:0305/122720.777894:1089216152:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ec0 [13307:13307:0305/122720.777929:1089216188:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (5 ms) [19/28] InvalidationClientImplTest.Start (5 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [13307:13307:0305/122720.778669:1089216930:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0 [13307:13307:0305/122720.778736:1089216995:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [ OK ] InvalidationClientImplTest.GenerateNonce (0 ms) [20/28] InvalidationClientImplTest.GenerateNonce (0 ms) [ RUN ] InvalidationClientImplTest.Register [13307:13307:0305/122720.779255:1089217515:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e80 with delay 0 [13307:13307:0305/122720.779316:1089217575:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13307:13307:0305/122720.779591:1089217854:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 0 [13307:13307:0305/122720.779645:1089217905:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e80 [13307:13307:0305/122720.779690:1089217948:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ee0 [13307:13307:0305/122720.779760:1089218019:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13307:13307:0305/122720.779821:1089218081:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0 [13307:13307:0305/122720.779869:1089218128:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20 [13307:13307:0305/122720.779904:1089218163:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13307:13307:0305/122720.779948:1089218207:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 0 [13307:13307:0305/122720.779985:1089218256:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ee0 [13307:13307:0305/122720.780033:1089218296:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13307:13307:0305/122720.780079:1089218343:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424 [13307:13307:0305/122720.780124:1089218384:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0 [13307:13307:0305/122720.780164:1089218422:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20 [13307:13307:0305/122720.780236:1089218495:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "2360396143280116873" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13307:13307:0305/122720.780275:1089218539:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9224 with a delay 500000, Now = 210919424 [13307:13307:0305/122720.780316:1089218575:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 500 [13307:13307:0305/122720.780355:1089218614:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424 [13307:13307:0305/122720.780394:1089218653:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f00 with delay 60000 [13307:13307:0305/122720.780447:1089218706:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ee0 [13307:13307:0305/122720.780484:1089218746:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.780536:1089218794:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.780682:1089218942: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: "2360396143280116873" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13307:13307:0305/122720.780803:1089219062:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 0 [13307:13307:0305/122720.780844:1089219104:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ee0 [13307:13307:0305/122720.780970:1089219230:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "2360396143280116873" 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" } } [13307:13307:0305/122720.781047:1089219309:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "2360396143280116873" [13307:13307:0305/122720.781089:1089219353:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13307:13307:0305/122720.781136:1089219395:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [13307:13307:0305/122720.781176:1089219435:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f10 with delay 1200000 [13307:13307:0305/122720.781218:1089219477:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13307:13307:0305/122720.781346:1089219606:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13307:13307:0305/122720.781392:1089219651:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424 [13307:13307:0305/122720.781430:1089219690:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0 [13307:13307:0305/122720.781488:1089219747: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 [13307:13307:0305/122720.781534:1089219792:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20 [13307:13307:0305/122720.781614:1089219874:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 0 [13307:13307:0305/122720.781666:1089219928:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424 [13307:13307:0305/122720.781706:1089219966:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e80 with delay 10000 [13307:13307:0305/122720.781745:1089220018:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f40 [13307:13307:0305/122720.781796:1089220055:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13307:13307:0305/122720.781883:1089220142:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f40 with delay 0 [13307:13307:0305/122720.781924:1089220183:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f40 [13307:13307:0305/122720.781976:1089220236:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [13307:13307:0305/122720.782039:1089220297:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [13307:13307:0305/122720.782086:1089220348:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [13307:13307:0305/122720.782175:1089220439:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9224 with a delay 500000, Now = 211469424 [13307:13307:0305/122720.782218:1089220477:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f20 with delay 500 [13307:13307:0305/122720.782259:1089220519:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9704 with a delay 60000000, Now = 211469424 [13307:13307:0305/122720.782301:1089220560:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f30 with delay 60000 [13307:13307:0305/122720.782358:1089220617:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20 [13307:13307:0305/122720.782398:1089220657:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.782450:1089220713:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.782490:1089220750:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13307:13307:0305/122720.782670:1089220931: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 } } } [13307:13307:0305/122720.782775:1089221035:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.782866:1089221126:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f20 with delay 0 [13307:13307:0305/122720.782909:1089221168:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20 [13307:13307:0305/122720.783165:1089221425: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 } } } } [13307:13307:0305/122720.783268:1089221528: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 [13307:13307:0305/122720.783362:1089221621:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [13307:13307:0305/122720.783483:1089221742:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [13307:13307:0305/122720.783571:1089221829:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [13307:13307:0305/122720.783872:1089222131:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e80 [ OK ] InvalidationClientImplTest.Register (7 ms) [21/28] InvalidationClientImplTest.Register (7 ms) [ RUN ] InvalidationClientImplTest.Invalidations [13307:13307:0305/122720.785513:1089223774:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000dc0 with delay 0 [13307:13307:0305/122720.785577:1089223835:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13307:13307:0305/122720.785964:1089224225:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 0 [13307:13307:0305/122720.786028:1089224288:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000dc0 [13307:13307:0305/122720.786066:1089224324:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c30 [13307:13307:0305/122720.786146:1089224405:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13307:13307:0305/122720.786208:1089224468:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f40 with delay 0 [13307:13307:0305/122720.786254:1089224513:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f40 [13307:13307:0305/122720.786289:1089224548:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13307:13307:0305/122720.786330:1089224589:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 0 [13307:13307:0305/122720.786377:1089224636:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c30 [13307:13307:0305/122720.786412:1089224672:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13307:13307:0305/122720.786455:1089224714:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424 [13307:13307:0305/122720.786494:1089224753:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f40 with delay 0 [13307:13307:0305/122720.786532:1089224790:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f40 [13307:13307:0305/122720.786604:1089224864:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-2277094100654161269" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13307:13307:0305/122720.786650:1089224909:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424 [13307:13307:0305/122720.786688:1089224948:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 500 [13307:13307:0305/122720.786726:1089224986:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424 [13307:13307:0305/122720.786765:1089225024:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ba0 with delay 60000 [13307:13307:0305/122720.786813:1089225072:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c30 [13307:13307:0305/122720.786853:1089225112:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.786900:1089225161:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.787053:1089225312: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: "-2277094100654161269" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13307:13307:0305/122720.787166:1089225427:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c30 with delay 0 [13307:13307:0305/122720.787206:1089225465:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c30 [13307:13307:0305/122720.787331:1089225592:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-2277094100654161269" 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" } } [13307:13307:0305/122720.787392:1089225652:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-2277094100654161269" [13307:13307:0305/122720.787434:1089225693:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13307:13307:0305/122720.787475:1089225734:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [13307:13307:0305/122720.787513:1089225772:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 1200000 [13307:13307:0305/122720.787553:1089225814:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13307:13307:0305/122720.787680:1089225940:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13307:13307:0305/122720.787722:1089225981:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424 [13307:13307:0305/122720.787762:1089226023:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 0 [13307:13307:0305/122720.787820:1089226080: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 [13307:13307:0305/122720.787868:1089226126:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f40 [13307:13307:0305/122720.787933:1089226192:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f70 with delay 0 [13307:13307:0305/122720.787979:1089226250:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424 [13307:13307:0305/122720.788031:1089226297:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000dc0 with delay 10000 [13307:13307:0305/122720.788083:1089226347:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f70 [13307:13307:0305/122720.788125:1089226385:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13307:13307:0305/122720.788182:1089226441:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.788247:1089226507:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f70 with delay 0 [13307:13307:0305/122720.788285:1089226546:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f70 [13307:13307:0305/122720.788506:1089226771: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 } } } [13307:13307:0305/122720.788611:1089226871: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 [13307:13307:0305/122720.788695:1089226954: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" } [13307:13307:0305/122720.788828:1089227087:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [13307:13307:0305/122720.788923:1089227182:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [13307:13307:0305/122720.789024:1089227283:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f70 with delay 0 [13307:13307:0305/122720.789062:1089227327:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f40 with delay 0 [13307:13307:0305/122720.789115:1089227374:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f50 with delay 0 [13307:13307:0305/122720.789153:1089227412:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f70 [13307:13307:0305/122720.789210:1089227469:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9896 with a delay 500000, Now = 211519424 [13307:13307:0305/122720.789250:1089227509:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000c30 with delay 500 [13307:13307:0305/122720.789298:1089227557:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f40 [13307:13307:0305/122720.789341:1089227599:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f50 [13307:13307:0305/122720.789392:1089227651:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x701000000c30 [13307:13307:0305/122720.789433:1089227693:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.789490:1089227756:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.789534:1089227793:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13307:13307:0305/122720.789726:1089227988: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) [22/28] InvalidationClientImplTest.Invalidations (5 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [13307:13307:0305/122720.790448:1089228708:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000eb0 with delay 0 [13307:13307:0305/122720.790512:1089228770:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13307:13307:0305/122720.790732:1089228991:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0 [13307:13307:0305/122720.790779:1089229038:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000eb0 [13307:13307:0305/122720.790821:1089229079:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10 [13307:13307:0305/122720.790889:1089229148:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13307:13307:0305/122720.790948:1089229208:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0 [13307:13307:0305/122720.791006:1089229264:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20 [13307:13307:0305/122720.791041:1089229303:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13307:13307:0305/122720.791115:1089229374:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0 [13307:13307:0305/122720.791156:1089229415:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10 [13307:13307:0305/122720.791190:1089229450:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13307:13307:0305/122720.791234:1089229492:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424 [13307:13307:0305/122720.791275:1089229534:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0 [13307:13307:0305/122720.791312:1089229570:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20 [13307:13307:0305/122720.791382:1089229641:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-7245746805187843547" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13307:13307:0305/122720.791424:1089229684:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424 [13307:13307:0305/122720.791468:1089229727:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 500 [13307:13307:0305/122720.791507:1089229766:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424 [13307:13307:0305/122720.791546:1089229812:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d40 with delay 60000 [13307:13307:0305/122720.791615:1089229884:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10 [13307:13307:0305/122720.791665:1089229924:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.791715:1089229975:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.791846:1089230107: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: "-7245746805187843547" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13307:13307:0305/122720.791957:1089230218:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d10 with delay 0 [13307:13307:0305/122720.792019:1089230278:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10 [13307:13307:0305/122720.792157:1089230418:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-7245746805187843547" 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" } } [13307:13307:0305/122720.792214:1089230474:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-7245746805187843547" [13307:13307:0305/122720.792254:1089230514:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13307:13307:0305/122720.792296:1089230555:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [13307:13307:0305/122720.792335:1089230594:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c00 with delay 1200000 [13307:13307:0305/122720.792376:1089230637:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13307:13307:0305/122720.792498:1089230757:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13307:13307:0305/122720.792539:1089230798:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424 [13307:13307:0305/122720.792575:1089230837:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0 [13307:13307:0305/122720.792636:1089230895: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 [13307:13307:0305/122720.792684:1089230942:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20 [13307:13307:0305/122720.792751:1089231010:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c20 with delay 0 [13307:13307:0305/122720.792800:1089231059:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424 [13307:13307:0305/122720.792839:1089231098:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000eb0 with delay 10000 [13307:13307:0305/122720.792878:1089231136:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c20 [13307:13307:0305/122720.792917:1089231176:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13307:13307:0305/122720.792971:1089231230:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.793043:1089231303:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000c20 with delay 0 [13307:13307:0305/122720.793081:1089231347:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000c20 [13307:13307:0305/122720.793217:1089231479: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 } } [13307:13307:0305/122720.793293:1089231555: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 [13307:13307:0305/122720.793344:1089231603:INFO:protocol-handler.cc(294)] Adding subtree: { } [13307:13307:0305/122720.793385:1089231644:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 10376 with a delay 500000, Now = 211469424 [13307:13307:0305/122720.793424:1089231683:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f20 with delay 500 [13307:13307:0305/122720.793466:1089231725:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [13307:13307:0305/122720.793750:1089232030: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 } [13307:13307:0305/122720.793856:1089232119:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20 [13307:13307:0305/122720.793900:1089232159:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.793979:1089232251:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.794029:1089232290:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13307:13307:0305/122720.795595:1089233855: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 } } [13307:13307:0305/122720.795927:1089234186:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000eb0 [ OK ] InvalidationClientImplTest.ServerRequests (7 ms) [23/28] InvalidationClientImplTest.ServerRequests (7 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [13307:13307:0305/122720.797495:1089235756:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0 [13307:13307:0305/122720.797561:1089235820:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13307:13307:0305/122720.797819:1089236079:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0 [13307:13307:0305/122720.797867:1089236127:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50 [13307:13307:0305/122720.797912:1089236170:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10 [13307:13307:0305/122720.797984:1089236257:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13307:13307:0305/122720.798057:1089236317:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ae0 with delay 0 [13307:13307:0305/122720.798108:1089236367:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ae0 [13307:13307:0305/122720.798143:1089236403:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13307:13307:0305/122720.798183:1089236442:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0 [13307:13307:0305/122720.798222:1089236480:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10 [13307:13307:0305/122720.798256:1089236515:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13307:13307:0305/122720.798299:1089236558:INFO:recurring-task.cc(55)] [Startup] Scheduling 9896 with a delay 0, Now = 210919424 [13307:13307:0305/122720.798336:1089236598:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ae0 with delay 0 [13307:13307:0305/122720.798376:1089236634:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ae0 [13307:13307:0305/122720.798444:1089236703:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "5076339386007162298" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13307:13307:0305/122720.798487:1089236746:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9512 with a delay 500000, Now = 210919424 [13307:13307:0305/122720.798526:1089236785:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 500 [13307:13307:0305/122720.798562:1089236824:INFO:recurring-task.cc(55)] [Retry] Scheduling 9896 with a delay 60000000, Now = 210919424 [13307:13307:0305/122720.798602:1089236861:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 60000 [13307:13307:0305/122720.798653:1089236912:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10 [13307:13307:0305/122720.798693:1089236952:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.798739:1089236999:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.798876:1089237135: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: "5076339386007162298" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13307:13307:0305/122720.798986:1089237258:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d10 with delay 0 [13307:13307:0305/122720.799042:1089237302:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10 [13307:13307:0305/122720.799170:1089237429:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "5076339386007162298" 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" } } [13307:13307:0305/122720.799231:1089237491:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "5076339386007162298" [13307:13307:0305/122720.799282:1089237542:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13307:13307:0305/122720.799325:1089237586:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [13307:13307:0305/122720.799364:1089237624:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b30 with delay 1200000 [13307:13307:0305/122720.799407:1089237667:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13307:13307:0305/122720.799534:1089237795:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13307:13307:0305/122720.799578:1089237841:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [13307:13307:0305/122720.799620:1089237879:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ae0 with delay 0 [13307:13307:0305/122720.799678:1089237940: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 [13307:13307:0305/122720.799727:1089237986:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ae0 [13307:13307:0305/122720.799793:1089238052:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000009e0 with delay 0 [13307:13307:0305/122720.799841:1089238100:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [13307:13307:0305/122720.799882:1089238141:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b50 with delay 10000 [13307:13307:0305/122720.799918:1089238176:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000009e0 [13307:13307:0305/122720.799952:1089238213:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13307:13307:0305/122720.800022:1089238291:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.800101:1089238361:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000009e0 with delay 0 [13307:13307:0305/122720.800144:1089238404:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000009e0 [13307:13307:0305/122720.800269:1089238529: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" } } [13307:13307:0305/122720.800347:1089238607: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 [13307:13307:0305/122720.800400:1089238663:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [13307:13307:0305/122720.800749:1089239009:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000b50 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (5 ms) [24/28] InvalidationClientImplTest.IncomingErrorMessage (5 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [13307:13307:0305/122720.802476:1089240737:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d90 with delay 0 [13307:13307:0305/122720.802542:1089240801:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13307:13307:0305/122720.802873:1089241136:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0 [13307:13307:0305/122720.802922:1089241182:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d90 [13307:13307:0305/122720.802964:1089241222:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e70 [13307:13307:0305/122720.803047:1089241309:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13307:13307:0305/122720.803120:1089241379:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f50 with delay 0 [13307:13307:0305/122720.803168:1089241426:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f50 [13307:13307:0305/122720.803210:1089241470:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13307:13307:0305/122720.803251:1089241513:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0 [13307:13307:0305/122720.803292:1089241550:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e70 [13307:13307:0305/122720.803327:1089241586:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13307:13307:0305/122720.803372:1089241631:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424 [13307:13307:0305/122720.803418:1089241677:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f50 with delay 0 [13307:13307:0305/122720.803460:1089241718:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f50 [13307:13307:0305/122720.803529:1089241788:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "8205423036013500622" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13307:13307:0305/122720.803570:1089241830:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424 [13307:13307:0305/122720.803610:1089241869:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 500 [13307:13307:0305/122720.803648:1089241907:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424 [13307:13307:0305/122720.803688:1089241947:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 60000 [13307:13307:0305/122720.803740:1089241999:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e70 [13307:13307:0305/122720.803777:1089242038:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.803827:1089242085:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.803967:1089242227: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: "8205423036013500622" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13307:13307:0305/122720.804103:1089242363:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e70 with delay 0 [13307:13307:0305/122720.804146:1089242405:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e70 [13307:13307:0305/122720.804274:1089242534:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "8205423036013500622" 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" } } [13307:13307:0305/122720.804334:1089242596:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "8205423036013500622" [13307:13307:0305/122720.804377:1089242637:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13307:13307:0305/122720.804423:1089242682:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [13307:13307:0305/122720.804473:1089242732:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 1200000 [13307:13307:0305/122720.804517:1089242776:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13307:13307:0305/122720.804642:1089242901:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13307:13307:0305/122720.804684:1089242943:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [13307:13307:0305/122720.804722:1089242981:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f50 with delay 0 [13307:13307:0305/122720.804779:1089243038: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 [13307:13307:0305/122720.804826:1089243084:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f50 [13307:13307:0305/122720.804892:1089243151:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f60 with delay 0 [13307:13307:0305/122720.804941:1089243200:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [13307:13307:0305/122720.804981:1089243255:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d90 with delay 10000 [13307:13307:0305/122720.805036:1089243294:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f60 [13307:13307:0305/122720.805069:1089243328:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13307:13307:0305/122720.805131:1089243390:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f60 with delay 0 [13307:13307:0305/122720.805169:1089243428:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f60 [13307:13307:0305/122720.805225:1089243484:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [13307:13307:0305/122720.805289:1089243548:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9896 with a delay 500000, Now = 211469424 [13307:13307:0305/122720.805329:1089243588:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f50 with delay 500 [13307:13307:0305/122720.805367:1089243628:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9224 with a delay 60000000, Now = 211469424 [13307:13307:0305/122720.805405:1089243664:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f70 with delay 60000 [13307:13307:0305/122720.805461:1089243721:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f50 [13307:13307:0305/122720.805506:1089243765:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.805554:1089243815:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.805596:1089243857:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13307:13307:0305/122720.805776:1089244038: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 } } } [13307:13307:0305/122720.805881:1089244140:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.805938:1089244197:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f50 with delay 0 [13307:13307:0305/122720.805979:1089244250:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f50 [13307:13307:0305/122720.806121:1089244381: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" } } [13307:13307:0305/122720.806197:1089244457: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 [13307:13307:0305/122720.806237:1089244496:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [13307:13307:0305/122720.806336:1089244595:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [13307:13307:0305/122720.806683:1089244942:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000d90 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms) [25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [13307:13307:0305/122720.808244:1089246504:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c20 with delay 0 [13307:13307:0305/122720.808307:1089246565:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13307:13307:0305/122720.808527:1089246787:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0 [13307:13307:0305/122720.808571:1089246830:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c20 [13307:13307:0305/122720.808611:1089246869:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50 [13307:13307:0305/122720.808681:1089246941:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13307:13307:0305/122720.808742:1089247002:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e20 with delay 0 [13307:13307:0305/122720.808786:1089247044:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e20 [13307:13307:0305/122720.808820:1089247081:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13307:13307:0305/122720.808862:1089247121:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0 [13307:13307:0305/122720.808901:1089247159:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50 [13307:13307:0305/122720.808936:1089247197:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13307:13307:0305/122720.809003:1089247263:INFO:recurring-task.cc(55)] [Startup] Scheduling 9800 with a delay 0, Now = 210919424 [13307:13307:0305/122720.809042:1089247304:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e20 with delay 0 [13307:13307:0305/122720.809082:1089247347:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e20 [13307:13307:0305/122720.809160:1089247419:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "248747909483240351" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13307:13307:0305/122720.809203:1089247463:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9608 with a delay 500000, Now = 210919424 [13307:13307:0305/122720.809245:1089247504:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 500 [13307:13307:0305/122720.809298:1089247557:INFO:recurring-task.cc(55)] [Retry] Scheduling 9800 with a delay 60000000, Now = 210919424 [13307:13307:0305/122720.809336:1089247598:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c50 with delay 60000 [13307:13307:0305/122720.809388:1089247647:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50 [13307:13307:0305/122720.809432:1089247691:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.809488:1089247750:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.809631:1089247891: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: "248747909483240351" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13307:13307:0305/122720.809746:1089248042:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b50 with delay 0 [13307:13307:0305/122720.809826:1089248085:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50 [13307:13307:0305/122720.809946:1089248205:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "248747909483240351" 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" } } [13307:13307:0305/122720.810016:1089248275:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "248747909483240351" [13307:13307:0305/122720.810059:1089248318:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13307:13307:0305/122720.810107:1089248366:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [13307:13307:0305/122720.810145:1089248410:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 1200000 [13307:13307:0305/122720.810191:1089248449:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13307:13307:0305/122720.810316:1089248575:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13307:13307:0305/122720.810355:1089248617:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [13307:13307:0305/122720.810395:1089248655:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e20 with delay 0 [13307:13307:0305/122720.810456:1089248716: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 [13307:13307:0305/122720.810510:1089248768:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e20 [13307:13307:0305/122720.810578:1089248839:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 0 [13307:13307:0305/122720.810628:1089248887:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [13307:13307:0305/122720.810667:1089248926:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c20 with delay 10000 [13307:13307:0305/122720.810704:1089248962:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50 [13307:13307:0305/122720.810738:1089249000:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13307:13307:0305/122720.810796:1089249055:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a50 with delay 0 [13307:13307:0305/122720.810836:1089249095:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a50 [13307:13307:0305/122720.810892:1089249151:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [13307:13307:0305/122720.810955:1089249214:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9608 with a delay 500000, Now = 211469424 [13307:13307:0305/122720.811012:1089249272:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000e20 with delay 500 [13307:13307:0305/122720.811055:1089249314:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9416 with a delay 60000000, Now = 211469424 [13307:13307:0305/122720.811097:1089249356:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000af0 with delay 60000 [13307:13307:0305/122720.811153:1089249412:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000e20 [13307:13307:0305/122720.811193:1089249452:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.811241:1089249500:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.811279:1089249538:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13307:13307:0305/122720.811417:1089249676: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 } } } [13307:13307:0305/122720.811713:1089249975:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c20 [13307:13307:0305/122720.812877:1089251135:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000c50 [13307:13307:0305/122720.812924:1089251182:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x701000000af0 [13307:13307:0305/122720.812986:1089251255: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 [13307:13307:0305/122720.813037:1089251296:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [13307:13307:0305/122720.813128:1089251388: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 } [13307:13307:0305/122720.813177:1089251438:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9608 with a delay 500000, Now = 271469424 [13307:13307:0305/122720.813215:1089251475:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c50 with delay 500 [13307:13307:0305/122720.813255:1089251514:INFO:recurring-task.cc(55)] [Retry] Scheduling 9416 with a delay 60000000, Now = 271469424 [13307:13307:0305/122720.813294:1089251554:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c20 with delay 60000 [13307:13307:0305/122720.813345:1089251604:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x701000000c50 [13307:13307:0305/122720.813382:1089251643:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.813435:1089251694:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.813474:1089251733:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13307:13307:0305/122720.813625:1089251889: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 (8 ms) [26/28] InvalidationClientImplTest.NetworkTimeouts (8 ms) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary [13307:13307:0305/122720.815448:1089253708:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e30 with delay 0 [13307:13307:0305/122720.815512:1089253771:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13307:13307:0305/122720.815722:1089253982:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0 [13307:13307:0305/122720.815765:1089254028:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e30 [13307:13307:0305/122720.815814:1089254074:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10 [13307:13307:0305/122720.815884:1089254143:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13307:13307:0305/122720.815945:1089254205:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0 [13307:13307:0305/122720.816007:1089254267:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0 [13307:13307:0305/122720.816047:1089254308:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13307:13307:0305/122720.816087:1089254353:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0 [13307:13307:0305/122720.816132:1089254390:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10 [13307:13307:0305/122720.816166:1089254426:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13307:13307:0305/122720.816211:1089254471:INFO:recurring-task.cc(55)] [Startup] Scheduling 10376 with a delay 0, Now = 210919424 [13307:13307:0305/122720.816250:1089254509:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0 [13307:13307:0305/122720.816286:1089254544:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0 [13307:13307:0305/122720.816356:1089254617:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "6945220065605591000" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13307:13307:0305/122720.816403:1089254662:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9992 with a delay 500000, Now = 210919424 [13307:13307:0305/122720.816443:1089254702:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 500 [13307:13307:0305/122720.816481:1089254740:INFO:recurring-task.cc(55)] [Retry] Scheduling 10376 with a delay 60000000, Now = 210919424 [13307:13307:0305/122720.816518:1089254777:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000dd0 with delay 60000 [13307:13307:0305/122720.816566:1089254828:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10 [13307:13307:0305/122720.816607:1089254866:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.816656:1089254915:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.816790:1089255052: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: "6945220065605591000" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13307:13307:0305/122720.816901:1089255161:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b10 with delay 0 [13307:13307:0305/122720.816945:1089255205:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10 [13307:13307:0305/122720.817081:1089255348:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "6945220065605591000" 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" } } [13307:13307:0305/122720.817146:1089255405:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "6945220065605591000" [13307:13307:0305/122720.817187:1089255446:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13307:13307:0305/122720.817229:1089255488:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424 [13307:13307:0305/122720.817268:1089255527:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e20 with delay 1200000 [13307:13307:0305/122720.817312:1089255571:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13307:13307:0305/122720.817437:1089255697:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13307:13307:0305/122720.817479:1089255738:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [13307:13307:0305/122720.817518:1089255777:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0 [13307:13307:0305/122720.817573:1089255832: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 [13307:13307:0305/122720.817622:1089255880:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0 [13307:13307:0305/122720.817689:1089255948:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 0 [13307:13307:0305/122720.817736:1089255995:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [13307:13307:0305/122720.817789:1089256048:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e30 with delay 10000 [13307:13307:0305/122720.817835:1089256093:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50 [13307:13307:0305/122720.817869:1089256128:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13307:13307:0305/122720.817924:1089256185:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.817973:1089256248:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a50 with delay 0 [13307:13307:0305/122720.818027:1089256285:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a50 [13307:13307:0305/122720.818123:1089256383: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" } } [13307:13307:0305/122720.818397:1089256656:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e30 [13307:13307:0305/122720.819393:1089257652: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 (4 ms) [27/28] InvalidationClientImplTest.NoRegistrationSummary (4 ms) [ RUN ] InvalidationClientImplTest.Heartbeats [13307:13307:0305/122720.819960:1089258220:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c90 with delay 0 [13307:13307:0305/122720.820036:1089258295:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13307:13307:0305/122720.820267:1089258530:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 0 [13307:13307:0305/122720.820321:1089258580:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c90 [13307:13307:0305/122720.820361:1089258619:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b70 [13307:13307:0305/122720.820429:1089258689:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13307:13307:0305/122720.820492:1089258752:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0 [13307:13307:0305/122720.820536:1089258794:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0 [13307:13307:0305/122720.820574:1089258834:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13307:13307:0305/122720.820614:1089258876:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 0 [13307:13307:0305/122720.820654:1089258912:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b70 [13307:13307:0305/122720.820688:1089258947:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13307:13307:0305/122720.820730:1089258990:INFO:recurring-task.cc(55)] [Startup] Scheduling 9704 with a delay 0, Now = 210919424 [13307:13307:0305/122720.820770:1089259029:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0 [13307:13307:0305/122720.820807:1089259065:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0 [13307:13307:0305/122720.820876:1089259137:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "7350534832621163732" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13307:13307:0305/122720.820918:1089259177:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424 [13307:13307:0305/122720.820956:1089259216:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 500 [13307:13307:0305/122720.821014:1089259274:INFO:recurring-task.cc(55)] [Retry] Scheduling 9704 with a delay 60000000, Now = 210919424 [13307:13307:0305/122720.821054:1089259314:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 60000 [13307:13307:0305/122720.821108:1089259371:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b70 [13307:13307:0305/122720.821149:1089259409:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.821203:1089259462:INFO:invalidation-client-core.cc(488)] Return client token = "" [13307:13307:0305/122720.821338:1089259600: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: "7350534832621163732" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13307:13307:0305/122720.821450:1089259709:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b70 with delay 0 [13307:13307:0305/122720.821488:1089259749:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b70 [13307:13307:0305/122720.821617:1089259876:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "7350534832621163732" 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" } } [13307:13307:0305/122720.821678:1089259937:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "7350534832621163732" [13307:13307:0305/122720.821726:1089259986:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13307:13307:0305/122720.821789:1089260048:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424 [13307:13307:0305/122720.821830:1089260089:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 1200000 [13307:13307:0305/122720.821876:1089260135:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13307:13307:0305/122720.822010:1089260269:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13307:13307:0305/122720.822052:1089260311:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [13307:13307:0305/122720.822096:1089260355:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0 [13307:13307:0305/122720.822153:1089260412: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 [13307:13307:0305/122720.822200:1089260458:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0 [13307:13307:0305/122720.822266:1089260525:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b10 with delay 0 [13307:13307:0305/122720.822311:1089260570:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [13307:13307:0305/122720.822350:1089260609:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c90 with delay 10000 [13307:13307:0305/122720.822387:1089260645:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10 [13307:13307:0305/122720.822420:1089260679:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13307:13307:0305/122720.822871:1089261145:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c90 [13307:13307:0305/122720.824126:1089262385:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000ac0 [13307:13307:0305/122720.850039:1089288299:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x701000000a50 [13307:13307:0305/122720.850116:1089288376:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13307:13307:0305/122720.850182:1089288442:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13307:13307:0305/122720.850231:1089288490:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [13307:13307:0305/122720.850433:1089288699: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 } [13307:13307:0305/122720.850499:1089288759:INFO:recurring-task.cc(55)] [Send-info] Scheduling 10376 with a delay 500000, Now = 1411419424 [13307:13307:0305/122720.850550:1089288810:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000ac0 with delay 500 [13307:13307:0305/122720.850596:1089288855:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424 [13307:13307:0305/122720.850634:1089288895:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000c90 with delay 1200000 [13307:13307:0305/122720.850685:1089288944:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x701000000ac0 [13307:13307:0305/122720.850722:1089288984:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.850798:1089289058:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13307:13307:0305/122720.850836:1089289096:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13307:13307:0305/122720.851089:1089289349: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) [28/28] InvalidationClientImplTest.Heartbeats (33 ms) SUCCESS: all tests passed. Tests took 0 seconds. 2019-03-05 12:29:46,408 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmp1HVDu8/43685b6db6321910'] 2019-03-05 12:29:46,409 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmp1HVDu8/43685b6db6321910/output.json'] 2019-03-05 12:29:46,409 - root: [INFO] merge_cmd: /b/swarming/w/ir/cache/vpython/ba947a/bin/python /b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/standard_gtest_merge.py --build-properties {"attempt_start_ts": 1551814694000000, "blamelist": ["bungeman@chromium.org"], "bot_id": "swarm1908-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:5071639625-1lppvbtck1morgivc6sq4dul7klu27sd@developer.gserviceaccount.com", "created_ts": 1551814721480501, "id": "8919798042567208160", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1394", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1504002/1", "cq_experimental:false", "user_agent:cq"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1394, "category": "cq", "got_angle_revision": "f094bac949922dabc3dd6944f3dec04111e953b6", "got_dawn_revision": "b47470daa7377a804df5d94e7a93b5925a57f84a", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "79d7f822d09d101a0ed5ae719b2d62f750c4cad2", "got_revision_cp": "refs/heads/master@{#637770}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "6641700a356c9a321198ea8beefcd9323a4da862", "got_v8_revision_cp": "refs/heads/7.4.282@{#1}", "got_webrtc_revision": "7949f215c1183d8bfc5b13f86594a03d3d648f68", "got_webrtc_revision_cp": "refs/heads/master@{#26971}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1504002, "patch_project": "chromium/src", "patch_ref": "refs/changes/02/1504002/1", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 1, "patch_storage": "gerrit", "path_config": "generic", "reason": "CQ", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src", "revision": "HEAD"} --summary-json /b/swarming/w/ir/tmp/t/tmp3rtNCY.json --task-output-dir /b/swarming/w/ir/tmp/t/tmp1HVDu8 -o /b/swarming/w/ir/tmp/t/tmpmnIpT_.json /b/swarming/w/ir/tmp/t/tmp1HVDu8/43685b6db6321910/output.json Running ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/standard_gtest_merge.py', '--build-properties', '{"attempt_start_ts": 1551814694000000, "blamelist": ["bungeman@chromium.org"], "bot_id": "swarm1908-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:5071639625-1lppvbtck1morgivc6sq4dul7klu27sd@developer.gserviceaccount.com", "created_ts": 1551814721480501, "id": "8919798042567208160", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1394", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1504002/1", "cq_experimental:false", "user_agent:cq"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1394, "category": "cq", "got_angle_revision": "f094bac949922dabc3dd6944f3dec04111e953b6", "got_dawn_revision": "b47470daa7377a804df5d94e7a93b5925a57f84a", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "79d7f822d09d101a0ed5ae719b2d62f750c4cad2", "got_revision_cp": "refs/heads/master@{#637770}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "6641700a356c9a321198ea8beefcd9323a4da862", "got_v8_revision_cp": "refs/heads/7.4.282@{#1}", "got_webrtc_revision": "7949f215c1183d8bfc5b13f86594a03d3d648f68", "got_webrtc_revision_cp": "refs/heads/master@{#26971}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1504002, "patch_project": "chromium/src", "patch_ref": "refs/changes/02/1504002/1", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 1, "patch_storage": "gerrit", "path_config": "generic", "reason": "CQ", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src", "revision": "HEAD"}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp3rtNCY.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmp1HVDu8', '-o', '/b/swarming/w/ir/tmp/t/tmpmnIpT_.json', '/b/swarming/w/ir/tmp/t/tmp1HVDu8/43685b6db6321910/output.json'] in None (env: None) Command ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/standard_gtest_merge.py', '--build-properties', '{"attempt_start_ts": 1551814694000000, "blamelist": ["bungeman@chromium.org"], "bot_id": "swarm1908-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:5071639625-1lppvbtck1morgivc6sq4dul7klu27sd@developer.gserviceaccount.com", "created_ts": 1551814721480501, "id": "8919798042567208160", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1394", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1504002/1", "cq_experimental:false", "user_agent:cq"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1394, "category": "cq", "got_angle_revision": "f094bac949922dabc3dd6944f3dec04111e953b6", "got_dawn_revision": "b47470daa7377a804df5d94e7a93b5925a57f84a", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "79d7f822d09d101a0ed5ae719b2d62f750c4cad2", "got_revision_cp": "refs/heads/master@{#637770}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "6641700a356c9a321198ea8beefcd9323a4da862", "got_v8_revision_cp": "refs/heads/7.4.282@{#1}", "got_webrtc_revision": "7949f215c1183d8bfc5b13f86594a03d3d648f68", "got_webrtc_revision_cp": "refs/heads/master@{#26971}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1504002, "patch_project": "chromium/src", "patch_ref": "refs/changes/02/1504002/1", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 1, "patch_storage": "gerrit", "path_config": "generic", "reason": "CQ", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src", "revision": "HEAD"}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp3rtNCY.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmp1HVDu8', '-o', '/b/swarming/w/ir/tmp/t/tmpmnIpT_.json', '/b/swarming/w/ir/tmp/t/tmp1HVDu8/43685b6db6321910/output.json'] returned exit code 0