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/tmpuEWYtW.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpKrt4ao --merge-script /b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --merge-script-stdout-file /b/swarming/w/ir/tmp/t/tmpHHUc7Nmerge_script_log --merge-additional-args '[]' --build-properties '{"blamelist": ["thakis@chromium.org"], "bot_id": "swarm1908-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:thakis@chromium.org", "created_ts": 1552948098667089, "id": "8918609610450674560", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1401", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1528472/1", "user_agent:git_cl_try"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1401, "category": "git_cl_try", "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "e613f9e78b0f43a2eff084aab079b00b4083ec11", "got_revision_cp": "refs/heads/master@{#641778}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1528472, "patch_project": "chromium/src", "patch_ref": "refs/changes/72/1528472/1", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 1, "patch_storage": "gerrit", "path_config": "generic", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src"}' --summary-json-file /b/swarming/w/ir/tmp/t/tmp1FsB2q.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/tmpZ04gO4.json in dir /b/swarming/w/ir/k: allow_subannotations: True cmd: ['python', '-u', '/b/swarming/w/ir/kitchen-checkout/build/scripts/tools/runit.py', '--show-path', '--with-third-party-lib', '--', 'python', '/b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/collect_task.py', '--verbose', '-o', '/b/swarming/w/ir/tmp/t/tmpuEWYtW.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpKrt4ao', '--merge-script', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--merge-script-stdout-file', '/b/swarming/w/ir/tmp/t/tmpHHUc7Nmerge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"blamelist": ["thakis@chromium.org"], "bot_id": "swarm1908-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:thakis@chromium.org", "created_ts": 1552948098667089, "id": "8918609610450674560", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1401", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1528472/1", "user_agent:git_cl_try"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1401, "category": "git_cl_try", "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "e613f9e78b0f43a2eff084aab079b00b4083ec11", "got_revision_cp": "refs/heads/master@{#641778}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1528472, "patch_project": "chromium/src", "patch_ref": "refs/changes/72/1528472/1", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 1, "patch_storage": "gerrit", "path_config": "generic", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src"}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmp1FsB2q.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/tmpZ04gO4.json'] env: {'CHROME_HEADLESS': '1'} env_prefixes: {'PATH': '/b/swarming/w/ir/cache/swarming_client'} env_suffixes: {} infra_step: False name_tokens: ('cacheinvalidation_unittests (with patch)',) ok_ret: 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: 44663 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/8918609610450674560 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/itCJCn47/luci_context.013675880 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: 43abbd09cbf32311 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-18 17:13:43,224 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmpKrt4ao' 2019-03-18 17:13:43,225 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmpKrt4ao' already exists! 2019-03-18 17:13:43,225 - root: [WARNING] task_output_dir existing content: [] 2019-03-18 17:13:43,225 - 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/tmpZ04gO4.json -output-dir /b/swarming/w/ir/tmp/t/tmpKrt4ao -task-summary-json /b/swarming/w/ir/tmp/t/tmp1FsB2q.json [D2019-03-18T17:13:43.232442-07:00 459 0 auth.go:1265] Minting a new token {"key":"luci_ctx/1c2a5ffc7c4321010c8f546eedb10895b039946752932e303cd9092611e396ba", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-18T17:13:43.232523-07:00 459 0 luci_ctx.go:138] POST http://127.0.0.1:39553/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/1c2a5ffc7c4321010c8f546eedb10895b039946752932e303cd9092611e396ba", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-18T17:13:43.234481-07:00 459 0 auth.go:1222] Token expires in 42m49.765571189s {"key":"luci_ctx/1c2a5ffc7c4321010c8f546eedb10895b039946752932e303cd9092611e396ba", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 43ac075953409a10: exit 0 Additional test environment: CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox CHROME_HEADLESS=1 G_SLICE=always-malloc LANG=en_US.UTF-8 LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer MSAN_OPTIONS=symbolize=0 handle_abort=1 NSS_DISABLE_ARENA_FREE_LIST=1 NSS_DISABLE_UNLOAD=1 Command: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioICnQrj/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 [4737:4737:0318/170911.070584:12357189640:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 0 [4737:4737:0318/170911.070654:12357189711:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b80 [4737:4737:0318/170911.071052:12357190116: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 } [4737:4737:0318/170911.071136:12357190187:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9224 with a delay 500000, Now = 210919424 [4737:4737:0318/170911.071183:12357190238:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b90 with delay 500 [4737:4737:0318/170911.071239:12357190290:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b90 [4737:4737:0318/170911.071361:12357190413:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [4737:4737:0318/170911.071408:12357190462:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (1 ms) [1/28] ProtocolHandlerTest.TokenMissing (1 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [4737:4737:0318/170911.071943:12357191000:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b90 with delay 0 [4737:4737:0318/170911.071998:12357191057:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b90 [4737:4737:0318/170911.072062:12357191114:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9320 with a delay 500000, Now = 210919424 [4737:4737:0318/170911.072106:12357191156:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 500 [4737:4737:0318/170911.072158:12357191215:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b80 [4737:4737:0318/170911.072274:12357191332:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [4737:4737:0318/170911.072359:12357191410: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 } [4737:4737:0318/170911.072461:12357191517: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 } } [4737:4737:0318/170911.072619:12357191681: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 } } } [4737:4737:0318/170911.072780:12357191834: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 [4737:4737:0318/170911.073302:12357192354:INFO:protocol-handler.cc(139)] Incoming message: { } [4737:4737:0318/170911.073348:12357192404:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [4737:4737:0318/170911.073396:12357192448:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [3/28] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [ RUN ] RecurringTaskTest.PeriodicTask [4737:4737:0318/170911.073696:12357192753:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 369177624 with a delay 10000, Now = 0 [4737:4737:0318/170911.073749:12357192803:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009f0 with delay 10 [4737:4737:0318/170911.073805:12357192862:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009f0 [4737:4737:0318/170911.073862:12357192920:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [4737:4737:0318/170911.073915:12357192968:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 10000 [4737:4737:0318/170911.073957:12357193013:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000000a00 with delay 60 [4737:4737:0318/170911.074007:12357193057:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x701000000a00 [4737:4737:0318/170911.074040:12357193090:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [4737:4737:0318/170911.074073:12357193123:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 70000 [4737:4737:0318/170911.074106:12357193156:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7010000009f0 with delay 60 [4737:4737:0318/170911.074140:12357193190:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7010000009f0 [4737:4737:0318/170911.074183:12357193233:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [4737:4737:0318/170911.074216:12357193266:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 130000 [4737:4737:0318/170911.074249:12357193299:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x701000000a00 with delay 60 [4737:4737:0318/170911.074284:12357193340:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x701000000a00 [4737:4737:0318/170911.074323:12357193373:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [4737:4737:0318/170911.074355:12357193405:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 190000 [4737:4737:0318/170911.074388:12357193438:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7010000009f0 with delay 60 [4737:4737:0318/170911.074422:12357193481:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7010000009f0 [4737:4737:0318/170911.074463:12357193513:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [4737:4737:0318/170911.074495:12357193545:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 250000 [4737:4737:0318/170911.074527:12357193577:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x701000000a00 with delay 60 [4737:4737:0318/170911.074561:12357193611:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x701000000a00 [4737:4737:0318/170911.074593:12357193643:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [4737:4737:0318/170911.074624:12357193674:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 310000 [4737:4737:0318/170911.074656:12357193706:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7010000009f0 with delay 60 [4737:4737:0318/170911.074690:12357193740:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7010000009f0 [4737:4737:0318/170911.074722:12357193772:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [4737:4737:0318/170911.074758:12357193808:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177624 with a delay 60000, Now = 370000 [4737:4737:0318/170911.074792:12357193842:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x701000000a00 with delay 60 [4737:4737:0318/170911.074833:12357193884:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x701000000a00 [4737:4737:0318/170911.074882:12357193940:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (3 ms) [4/28] RecurringTaskTest.PeriodicTask (3 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [4737:4737:0318/170911.076135:12357195188:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 369177440 with a delay 10000, Now = 0 [4737:4737:0318/170911.076194:12357195245:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000000a00 with delay 10 [4737:4737:0318/170911.076233:12357195289:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000000a00 [4737:4737:0318/170911.076280:12357195336:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [4737:4737:0318/170911.076328:12357195378:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 50000, Now = 10000 [4737:4737:0318/170911.076364:12357195414:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 50 [4737:4737:0318/170911.076403:12357195464:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7010000009f0 [4737:4737:0318/170911.076469:12357195521:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [4737:4737:0318/170911.076508:12357195561:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 149000, Now = 60000 [4737:4737:0318/170911.076546:12357195602:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x701000000a00 with delay 149 [4737:4737:0318/170911.076608:12357195660:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x701000000a00 [4737:4737:0318/170911.076650:12357195700:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [4737:4737:0318/170911.076685:12357195741:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 248000, Now = 210000 [4737:4737:0318/170911.076737:12357195788:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7010000009f0 with delay 248 [4737:4737:0318/170911.076793:12357195850:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7010000009f0 [4737:4737:0318/170911.076852:12357195903:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [4737:4737:0318/170911.076888:12357195946:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 446000, Now = 460000 [4737:4737:0318/170911.076938:12357195995:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x701000000a00 with delay 446 [4737:4737:0318/170911.077025:12357196076:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x701000000a00 [4737:4737:0318/170911.077061:12357196114:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [4737:4737:0318/170911.077099:12357196149:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 842000, Now = 910000 [4737:4737:0318/170911.077136:12357196187:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7010000009f0 with delay 842 [4737:4737:0318/170911.077205:12357196255:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7010000009f0 [4737:4737:0318/170911.077238:12357196287:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [4737:4737:0318/170911.077278:12357196333:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 1040000, Now = 1760000 [4737:4737:0318/170911.077317:12357196367:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x701000000a00 with delay 1040 [4737:4737:0318/170911.077376:12357196426:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x701000000a00 [4737:4737:0318/170911.077408:12357196458:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [4737:4737:0318/170911.077448:12357196498:INFO:recurring-task.cc(55)] [Retry] Scheduling 369177440 with a delay 1040000, Now = 2800000 [4737:4737:0318/170911.077484:12357196534:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7010000009f0 with delay 1040 [4737:4737:0318/170911.077543:12357196593:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7010000009f0 [4737:4737:0318/170911.077575:12357196624:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (2 ms) [5/28] RecurringTaskTest.ExponentialBackoffTask (2 ms) [ RUN ] RecurringTaskTest.OneShotTask [4737:4737:0318/170911.078854:12357197912:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 369177480 with a delay 10000, Now = 0 [4737:4737:0318/170911.078906:12357197957:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000009f0 with delay 10 [4737:4737:0318/170911.078958:12357198011:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000009f0 [4737:4737:0318/170911.078998:12357198054:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [4737:4737:0318/170911.079052:12357198107:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 369177480 with a delay 10000, Now = 10000 [4737:4737:0318/170911.079098:12357198149:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 10 [4737:4737:0318/170911.079140:12357198203:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7010000009f0 [4737:4737:0318/170911.079196:12357198253:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (2 ms) [6/28] RecurringTaskTest.OneShotTask (2 ms) [ RUN ] ThrottleTest.ThrottlingScripted [4737:4737:0318/170911.080496:12357199551:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7010000009f0 with delay 920 [4737:4737:0318/170911.080564:12357199614:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009f0 [4737:4737:0318/170911.080949:12357199999:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7010000009f0 with delay 45000 [4737:4737:0318/170911.082155:12357201206:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000009f0 [ OK ] ThrottleTest.ThrottlingScripted (2 ms) [7/28] ThrottleTest.ThrottlingScripted (2 ms) [ RUN ] ThrottleTest.ThrottlingStorm [4737:4737:0318/170911.082308:12357201358:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000009f0 with delay 990 [4737:4737:0318/170911.082375:12357201426:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000009f0 [4737:4737:0318/170911.082423:12357201483:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.082500:12357201549:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7010000009f0 [4737:4737:0318/170911.082535:12357201584:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.082595:12357201644:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7010000009f0 [4737:4737:0318/170911.082628:12357201678:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.082689:12357201738:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7010000009f0 [4737:4737:0318/170911.082722:12357201772:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.082782:12357201834:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7010000009f0 [4737:4737:0318/170911.082818:12357201868:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.082878:12357201927:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7010000009f0 [4737:4737:0318/170911.082914:12357201965:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x701000000a00 with delay 54000 [4737:4737:0318/170911.084551:12357203601:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x701000000a00 [4737:4737:0318/170911.084590:12357203640:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x701000000a00 with delay 1000 [4737:4737:0318/170911.084658:12357203707:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x701000000a00 [4737:4737:0318/170911.084691:12357203741:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x701000000a00 with delay 1000 [4737:4737:0318/170911.084752:12357203801:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x701000000a00 [4737:4737:0318/170911.084785:12357203837:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x701000000a00 with delay 1000 [4737:4737:0318/170911.084848:12357203898:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x701000000a00 [4737:4737:0318/170911.084882:12357203932:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x701000000a00 with delay 1000 [4737:4737:0318/170911.084942:12357203991:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x701000000a00 [4737:4737:0318/170911.084993:12357204042:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x701000000a00 with delay 1000 [4737:4737:0318/170911.085053:12357204103:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x701000000a00 [4737:4737:0318/170911.085087:12357204136:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x701000000a00 with delay 1000 [4737:4737:0318/170911.085146:12357204196:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x701000000a00 [4737:4737:0318/170911.085183:12357204233:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7010000009f0 with delay 54000 [4737:4737:0318/170911.086804:12357205854:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7010000009f0 [4737:4737:0318/170911.086844:12357205893:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.086904:12357205954:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7010000009f0 [4737:4737:0318/170911.086937:12357205987:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.086997:12357206046:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7010000009f0 [4737:4737:0318/170911.087030:12357206079:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.087090:12357206139:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7010000009f0 [4737:4737:0318/170911.087123:12357206172:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.087183:12357206232:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7010000009f0 [4737:4737:0318/170911.087216:12357206266:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.087276:12357206330:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7010000009f0 [4737:4737:0318/170911.087314:12357206364:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.087374:12357206423:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7010000009f0 [4737:4737:0318/170911.087407:12357206457:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x701000000a00 with delay 54000 [4737:4737:0318/170911.089030:12357208080:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x701000000a00 [4737:4737:0318/170911.089068:12357208118:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x701000000a00 with delay 1000 [4737:4737:0318/170911.089129:12357208178:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x701000000a00 [4737:4737:0318/170911.089163:12357208212:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x701000000a00 with delay 1000 [4737:4737:0318/170911.089222:12357208272:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x701000000a00 [4737:4737:0318/170911.089261:12357208311:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x701000000a00 with delay 1000 [4737:4737:0318/170911.089325:12357208375:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x701000000a00 [4737:4737:0318/170911.089359:12357208408:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x701000000a00 with delay 1000 [4737:4737:0318/170911.089419:12357208475:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x701000000a00 [4737:4737:0318/170911.089460:12357208509:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x701000000a00 with delay 1000 [4737:4737:0318/170911.089520:12357208569:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x701000000a00 [4737:4737:0318/170911.089553:12357208602:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x701000000a00 with delay 1000 [4737:4737:0318/170911.089613:12357208662:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x701000000a00 [4737:4737:0318/170911.089645:12357208695:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7010000009f0 with delay 54000 [4737:4737:0318/170911.091255:12357210305:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7010000009f0 [4737:4737:0318/170911.091296:12357210346:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.091361:12357210411:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7010000009f0 [4737:4737:0318/170911.091395:12357210444:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.091461:12357210511:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7010000009f0 [4737:4737:0318/170911.091495:12357210544:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.091555:12357210604:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7010000009f0 [4737:4737:0318/170911.091588:12357210637:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.091648:12357210697:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7010000009f0 [4737:4737:0318/170911.091681:12357210730:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.091741:12357210790:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7010000009f0 [4737:4737:0318/170911.091774:12357210824:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7010000009f0 with delay 1000 [4737:4737:0318/170911.091836:12357210886:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7010000009f0 [4737:4737:0318/170911.091869:12357210919:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x701000000a00 with delay 54000 [4737:4737:0318/170911.093530:12357212581:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x701000000a00 [ OK ] ThrottleTest.ThrottlingStorm (11 ms) [8/28] ThrottleTest.ThrottlingStorm (11 ms) [ RUN ] ProtocolHandlerTest.SendInitializeOnly [4736:4736:0318/170911.044905:12357163960:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b80 with delay 0 [4736:4736:0318/170911.045268:12357164326:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b80 [4736:4736:0318/170911.045634:12357164685: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 } [4736:4736:0318/170911.045700:12357164752:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 500000, Now = 210919424 [4736:4736:0318/170911.045747:12357164798:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c10 with delay 500 [4736:4736:0318/170911.045808:12357164860:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c10 [4736:4736:0318/170911.046102:12357165155:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "unit-test-nonce" application_client_id: { client_type: 2 client_name: "unit-test-client-id" } digest_serialization_type: BYTE_BASED } } [ OK ] ProtocolHandlerTest.SendInitializeOnly (2 ms) [9/28] ProtocolHandlerTest.SendInitializeOnly (2 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [4736:4736:0318/170911.047375:12357166428: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 [4736:4736:0318/170911.047891:12357166944:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0 [4736:4736:0318/170911.047967:12357167023:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b40 with delay 0 [4736:4736:0318/170911.048020:12357167076:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 0 [4736:4736:0318/170911.048094:12357167145:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b00 with delay 0 [4736:4736:0318/170911.048140:12357167190:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ab0 with delay 0 [4736:4736:0318/170911.048184:12357167235:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0 [4736:4736:0318/170911.048601:12357167653:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10 [4736:4736:0318/170911.048759:12357167811: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 } [4736:4736:0318/170911.048819:12357167870:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9320 with a delay 500000, Now = 210919424 [4736:4736:0318/170911.048866:12357167918:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c60 with delay 500 [4736:4736:0318/170911.048910:12357167959:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b40 [4736:4736:0318/170911.048951:12357168024:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ac0 [4736:4736:0318/170911.049021:12357168071:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b00 [4736:4736:0318/170911.049063:12357168112:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ab0 [4736:4736:0318/170911.049099:12357168160:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0 [4736:4736:0318/170911.049167:12357168217:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [4736:4736:0318/170911.049224:12357168274:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c60 [4736:4736:0318/170911.049446:12357168496:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [4736:4736:0318/170911.050828:12357169882: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 [4736:4736:0318/170911.052582:12357171639: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 [4736:4736:0318/170911.053286:12357172349: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 } } [4736:4736:0318/170911.053392:12357172443: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" } [4736:4736:0318/170911.053514:12357172566: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 } } [4736:4736:0318/170911.053626:12357172677: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 [4736:4736:0318/170911.054170:12357173222: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 } } [4736:4736:0318/170911.054309:12357173360: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 [4736:4736:0318/170911.054823:12357173874: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 [4736:4736:0318/170911.055333:12357174385: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" } } [4736:4736:0318/170911.055411:12357174479:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a40 with delay 0 [4736:4736:0318/170911.055471:12357174535:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000a40 [4736:4736:0318/170911.055577:12357174630: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 } [4736:4736:0318/170911.055637:12357174688:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9704 with a delay 500000, Now = 210919424 [4736:4736:0318/170911.055676:12357174735:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000a50 with delay 500 [4736:4736:0318/170911.055736:12357174790:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50 [4736:4736:0318/170911.055781:12357174832:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 [ OK ] ProtocolHandlerTest.ConfigMessage (46 ms) [16/28] ProtocolHandlerTest.ConfigMessage (46 ms) [ RUN ] ProtocolHandlerTest.ErrorMessage [4736:4736:0318/170911.101617:12357220671:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.ErrorMessage (0 ms) [17/28] ProtocolHandlerTest.ErrorMessage (0 ms) [ RUN ] ProtocolHandlerTest.TokenMismatch [4736:4736:0318/170911.102180:12357221238:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.TokenMismatch (1 ms) [18/28] ProtocolHandlerTest.TokenMismatch (1 ms) [ RUN ] InvalidationClientImplTest.Start [4734:4734:0318/170911.016486:12357135542:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c80 with delay 0 [4734:4734:0318/170911.016878:12357135938:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4734:4734:0318/170911.017261:12357136314:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0 [4734:4734:0318/170911.017311:12357136365:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c80 [4734:4734:0318/170911.017352:12357136402:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50 [4734:4734:0318/170911.017446:12357136497:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4734:4734:0318/170911.017539:12357136590:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ea0 with delay 0 [4734:4734:0318/170911.017588:12357136638:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ea0 [4734:4734:0318/170911.017622:12357136673:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4734:4734:0318/170911.017676:12357136727:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 0 [4734:4734:0318/170911.017719:12357136769:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e50 [4734:4734:0318/170911.017766:12357136817:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4734:4734:0318/170911.017810:12357136861:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 0, Now = 210919424 [4734:4734:0318/170911.017849:12357136900:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ea0 with delay 0 [4734:4734:0318/170911.017888:12357136938:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ea0 [4734:4734:0318/170911.017978:12357137028:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-7205043523080705347" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4734:4734:0318/170911.018027:12357137079:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9416 with a delay 500000, Now = 210919424 [4734:4734:0318/170911.018074:12357137125:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e50 with delay 500 [4734:4734:0318/170911.018115:12357137166:INFO:recurring-task.cc(55)] [Retry] Scheduling 9224 with a delay 60000000, Now = 210919424 [4734:4734:0318/170911.018163:12357137213:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e10 with delay 60000 [4734:4734:0318/170911.018220:12357137280:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50 [4734:4734:0318/170911.018285:12357137335:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.018361:12357137415:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.018577:12357137628: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: "-7205043523080705347" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4734:4734:0318/170911.018836:12357137887:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e50 with delay 0 [4734:4734:0318/170911.018892:12357137943:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e50 [4734:4734:0318/170911.019042:12357138093:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-7205043523080705347" 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" } } [4734:4734:0318/170911.019114:12357138164:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-7205043523080705347" [4734:4734:0318/170911.019154:12357138204:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4734:4734:0318/170911.019197:12357138253:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [4734:4734:0318/170911.019250:12357138300:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e90 with delay 1200000 [4734:4734:0318/170911.019305:12357138356:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4734:4734:0318/170911.019484:12357138539:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4734:4734:0318/170911.019533:12357138588:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424 [4734:4734:0318/170911.019574:12357138630:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ea0 with delay 0 [4734:4734:0318/170911.019678:12357138729: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 [4734:4734:0318/170911.019739:12357138793:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ea0 [4734:4734:0318/170911.019837:12357138888:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ec0 with delay 0 [4734:4734:0318/170911.019887:12357138938:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424 [4734:4734:0318/170911.019926:12357138977:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c80 with delay 10000 [4734:4734:0318/170911.019965:12357139015:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ec0 [4734:4734:0318/170911.019999:12357139050:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (5 ms) [19/28] InvalidationClientImplTest.Start (5 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [4734:4734:0318/170911.020877:12357139928:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0 [4734:4734:0318/170911.020941:12357139991:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [ OK ] InvalidationClientImplTest.GenerateNonce (1 ms) [20/28] InvalidationClientImplTest.GenerateNonce (1 ms) [ RUN ] InvalidationClientImplTest.Register [4734:4734:0318/170911.021581:12357140634:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e80 with delay 0 [4734:4734:0318/170911.021646:12357140696:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4734:4734:0318/170911.021943:12357140994:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 0 [4734:4734:0318/170911.021997:12357141048:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e80 [4734:4734:0318/170911.022038:12357141088:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ee0 [4734:4734:0318/170911.022107:12357141158:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4734:4734:0318/170911.022176:12357141232:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0 [4734:4734:0318/170911.022240:12357141290:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20 [4734:4734:0318/170911.022275:12357141329:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4734:4734:0318/170911.022324:12357141374:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 0 [4734:4734:0318/170911.022363:12357141418:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ee0 [4734:4734:0318/170911.022406:12357141456:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4734:4734:0318/170911.022461:12357141512:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424 [4734:4734:0318/170911.022510:12357141564:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0 [4734:4734:0318/170911.022554:12357141604:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20 [4734:4734:0318/170911.022639:12357141692:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "7458590634550464377" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4734:4734:0318/170911.022688:12357141739:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9224 with a delay 500000, Now = 210919424 [4734:4734:0318/170911.022726:12357141779:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ee0 with delay 500 [4734:4734:0318/170911.022765:12357141816:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424 [4734:4734:0318/170911.022810:12357141861:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f00 with delay 60000 [4734:4734:0318/170911.022864:12357141915:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ee0 [4734:4734:0318/170911.022901:12357141954:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.022952:12357142002:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.023095:12357142147: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: "7458590634550464377" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4734:4734:0318/170911.023240:12357142291:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 0 [4734:4734:0318/170911.023283:12357142338:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ee0 [4734:4734:0318/170911.023420:12357142482:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "7458590634550464377" 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" } } [4734:4734:0318/170911.023495:12357142546:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "7458590634550464377" [4734:4734:0318/170911.023544:12357142594:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4734:4734:0318/170911.023587:12357142638:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [4734:4734:0318/170911.023624:12357142677:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f10 with delay 1200000 [4734:4734:0318/170911.023666:12357142716:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4734:4734:0318/170911.023805:12357142857:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4734:4734:0318/170911.023846:12357142897:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424 [4734:4734:0318/170911.023888:12357142938:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0 [4734:4734:0318/170911.023946:12357142996: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 [4734:4734:0318/170911.024005:12357143055:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20 [4734:4734:0318/170911.024079:12357143130:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 0 [4734:4734:0318/170911.024133:12357143186:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424 [4734:4734:0318/170911.024175:12357143225:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e80 with delay 10000 [4734:4734:0318/170911.024213:12357143263:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f40 [4734:4734:0318/170911.024253:12357143303:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4734:4734:0318/170911.024340:12357143391:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f40 with delay 0 [4734:4734:0318/170911.024382:12357143432:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f40 [4734:4734:0318/170911.024443:12357143500:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [4734:4734:0318/170911.024497:12357143547:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [4734:4734:0318/170911.024545:12357143595:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [4734:4734:0318/170911.024643:12357143694:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9224 with a delay 500000, Now = 211469424 [4734:4734:0318/170911.024686:12357143738:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f20 with delay 500 [4734:4734:0318/170911.024729:12357143782:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9704 with a delay 60000000, Now = 211469424 [4734:4734:0318/170911.024767:12357143817:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f30 with delay 60000 [4734:4734:0318/170911.024825:12357143881:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20 [4734:4734:0318/170911.024869:12357143919:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.024924:12357143975:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.024961:12357144032:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4734:4734:0318/170911.025166:12357144220: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 } } } [4734:4734:0318/170911.025278:12357144329:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.025367:12357144424:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f20 with delay 0 [4734:4734:0318/170911.025419:12357144479:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20 [4734:4734:0318/170911.025670:12357144724: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 } } } } [4734:4734:0318/170911.025792:12357144847: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 [4734:4734:0318/170911.025898:12357144957:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [4734:4734:0318/170911.026046:12357145100:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [4734:4734:0318/170911.026149:12357145203:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [4734:4734:0318/170911.026482:12357145533:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e80 [ OK ] InvalidationClientImplTest.Register (6 ms) [21/28] InvalidationClientImplTest.Register (6 ms) [ RUN ] InvalidationClientImplTest.Invalidations [4734:4734:0318/170911.028277:12357147330:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000dc0 with delay 0 [4734:4734:0318/170911.028344:12357147394:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4734:4734:0318/170911.028712:12357147763:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 0 [4734:4734:0318/170911.028766:12357147816:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000dc0 [4734:4734:0318/170911.028809:12357147859:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c30 [4734:4734:0318/170911.028885:12357147938:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4734:4734:0318/170911.028956:12357148022:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f40 with delay 0 [4734:4734:0318/170911.029024:12357148077:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f40 [4734:4734:0318/170911.029066:12357148116:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4734:4734:0318/170911.029103:12357148156:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 0 [4734:4734:0318/170911.029143:12357148197:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c30 [4734:4734:0318/170911.029195:12357148246:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4734:4734:0318/170911.029254:12357148305:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424 [4734:4734:0318/170911.029311:12357148361:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f40 with delay 0 [4734:4734:0318/170911.029349:12357148399:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f40 [4734:4734:0318/170911.029424:12357148482:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-4727764432818465460" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4734:4734:0318/170911.029476:12357148527:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424 [4734:4734:0318/170911.029523:12357148574:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 500 [4734:4734:0318/170911.029562:12357148613:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424 [4734:4734:0318/170911.029598:12357148649:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ba0 with delay 60000 [4734:4734:0318/170911.029649:12357148700:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c30 [4734:4734:0318/170911.029688:12357148738:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.029740:12357148790:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.029878:12357148929: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: "-4727764432818465460" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4734:4734:0318/170911.029996:12357149047:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c30 with delay 0 [4734:4734:0318/170911.030037:12357149088:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c30 [4734:4734:0318/170911.030173:12357149223:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-4727764432818465460" 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" } } [4734:4734:0318/170911.030240:12357149298:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-4727764432818465460" [4734:4734:0318/170911.030294:12357149345:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4734:4734:0318/170911.030337:12357149390:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [4734:4734:0318/170911.030379:12357149429:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 1200000 [4734:4734:0318/170911.030418:12357149483:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4734:4734:0318/170911.030558:12357149608:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4734:4734:0318/170911.030597:12357149649:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424 [4734:4734:0318/170911.030634:12357149684:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 0 [4734:4734:0318/170911.030697:12357149750: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 [4734:4734:0318/170911.030750:12357149802:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f40 [4734:4734:0318/170911.030835:12357149886:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f70 with delay 0 [4734:4734:0318/170911.030888:12357149938:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424 [4734:4734:0318/170911.030924:12357149980:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000dc0 with delay 10000 [4734:4734:0318/170911.030966:12357150016:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f70 [4734:4734:0318/170911.031005:12357150055:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4734:4734:0318/170911.031064:12357150115:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.031129:12357150180:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f70 with delay 0 [4734:4734:0318/170911.031169:12357150220:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f70 [4734:4734:0318/170911.031399:12357150450: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 } } } [4734:4734:0318/170911.031505:12357150556: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 [4734:4734:0318/170911.031589:12357150640: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" } [4734:4734:0318/170911.031744:12357150798:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [4734:4734:0318/170911.031851:12357150901:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [4734:4734:0318/170911.031945:12357150996:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f70 with delay 0 [4734:4734:0318/170911.031986:12357151037:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f40 with delay 0 [4734:4734:0318/170911.032025:12357151075:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000f50 with delay 0 [4734:4734:0318/170911.032065:12357151116:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f70 [4734:4734:0318/170911.032121:12357151172:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9896 with a delay 500000, Now = 211519424 [4734:4734:0318/170911.032162:12357151215:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000c30 with delay 500 [4734:4734:0318/170911.032206:12357151257:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f40 [4734:4734:0318/170911.032260:12357151313:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000f50 [4734:4734:0318/170911.032316:12357151366:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x701000000c30 [4734:4734:0318/170911.032360:12357151411:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.032421:12357151481:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.032471:12357151522:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4734:4734:0318/170911.032661:12357151712: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 (6 ms) [22/28] InvalidationClientImplTest.Invalidations (6 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [4734:4734:0318/170911.033472:12357152525:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000eb0 with delay 0 [4734:4734:0318/170911.033541:12357152592:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4734:4734:0318/170911.033775:12357152833:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0 [4734:4734:0318/170911.033828:12357152880:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000eb0 [4734:4734:0318/170911.033870:12357152920:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10 [4734:4734:0318/170911.033940:12357152994:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4734:4734:0318/170911.034004:12357153055:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0 [4734:4734:0318/170911.034050:12357153100:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20 [4734:4734:0318/170911.034085:12357153136:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4734:4734:0318/170911.034122:12357153174:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0 [4734:4734:0318/170911.034161:12357153211:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10 [4734:4734:0318/170911.034196:12357153246:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4734:4734:0318/170911.034246:12357153297:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424 [4734:4734:0318/170911.034295:12357153354:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f20 with delay 0 [4734:4734:0318/170911.034352:12357153411:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f20 [4734:4734:0318/170911.034467:12357153531:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-1256292921504706621" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4734:4734:0318/170911.034529:12357153583:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424 [4734:4734:0318/170911.034576:12357153626:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 500 [4734:4734:0318/170911.034619:12357153672:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424 [4734:4734:0318/170911.034658:12357153709:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d40 with delay 60000 [4734:4734:0318/170911.034709:12357153763:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10 [4734:4734:0318/170911.034759:12357153813:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.034816:12357153866:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.034959:12357154009: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: "-1256292921504706621" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4734:4734:0318/170911.035081:12357154132:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d10 with delay 0 [4734:4734:0318/170911.035122:12357154173:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10 [4734:4734:0318/170911.035259:12357154309:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-1256292921504706621" 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" } } [4734:4734:0318/170911.035317:12357154370:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-1256292921504706621" [4734:4734:0318/170911.035361:12357154412:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4734:4734:0318/170911.035404:12357154455:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [4734:4734:0318/170911.035454:12357154504:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c00 with delay 1200000 [4734:4734:0318/170911.035493:12357154550:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4734:4734:0318/170911.035650:12357154701:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4734:4734:0318/170911.035690:12357154741:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424 [4734:4734:0318/170911.035729:12357154782:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f20 with delay 0 [4734:4734:0318/170911.035805:12357154858: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 [4734:4734:0318/170911.035857:12357154907:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f20 [4734:4734:0318/170911.035931:12357154981:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c20 with delay 0 [4734:4734:0318/170911.035977:12357155028:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424 [4734:4734:0318/170911.036014:12357155068:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000eb0 with delay 10000 [4734:4734:0318/170911.036054:12357155104:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000c20 [4734:4734:0318/170911.036088:12357155142:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4734:4734:0318/170911.036154:12357155207:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.036229:12357155285:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000c20 with delay 0 [4734:4734:0318/170911.036279:12357155329:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000c20 [4734:4734:0318/170911.036420:12357155482: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 } } [4734:4734:0318/170911.036508:12357155560: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 [4734:4734:0318/170911.036556:12357155606:INFO:protocol-handler.cc(294)] Adding subtree: { } [4734:4734:0318/170911.036596:12357155647:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 10376 with a delay 500000, Now = 211469424 [4734:4734:0318/170911.036634:12357155685:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f20 with delay 500 [4734:4734:0318/170911.036672:12357155728:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [4734:4734:0318/170911.036929:12357155980: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 } [4734:4734:0318/170911.037021:12357156072:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f20 [4734:4734:0318/170911.037063:12357156113:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.037140:12357156191:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.037178:12357156228:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4734:4734:0318/170911.038380:12357157435: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 } } [4734:4734:0318/170911.038771:12357157822:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000eb0 [ OK ] InvalidationClientImplTest.ServerRequests (7 ms) [23/28] InvalidationClientImplTest.ServerRequests (7 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [4734:4734:0318/170911.040456:12357159509:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0 [4734:4734:0318/170911.040525:12357159575:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4734:4734:0318/170911.040778:12357159829:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0 [4734:4734:0318/170911.040821:12357159872:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50 [4734:4734:0318/170911.040862:12357159912:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10 [4734:4734:0318/170911.040931:12357159982:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4734:4734:0318/170911.041016:12357160067:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ae0 with delay 0 [4734:4734:0318/170911.041063:12357160113:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ae0 [4734:4734:0318/170911.041097:12357160148:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4734:4734:0318/170911.041137:12357160188:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 0 [4734:4734:0318/170911.041176:12357160226:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d10 [4734:4734:0318/170911.041211:12357160261:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4734:4734:0318/170911.041258:12357160309:INFO:recurring-task.cc(55)] [Startup] Scheduling 9896 with a delay 0, Now = 210919424 [4734:4734:0318/170911.041296:12357160346:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ae0 with delay 0 [4734:4734:0318/170911.041334:12357160384:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000ae0 [4734:4734:0318/170911.041406:12357160456:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1603052231409875050" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4734:4734:0318/170911.041457:12357160508:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9512 with a delay 500000, Now = 210919424 [4734:4734:0318/170911.041493:12357160546:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d10 with delay 500 [4734:4734:0318/170911.041532:12357160582:INFO:recurring-task.cc(55)] [Retry] Scheduling 9896 with a delay 60000000, Now = 210919424 [4734:4734:0318/170911.041573:12357160624:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ad0 with delay 60000 [4734:4734:0318/170911.041624:12357160675:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10 [4734:4734:0318/170911.041661:12357160711:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.041714:12357160764:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.041851:12357160904: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: "1603052231409875050" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4734:4734:0318/170911.041976:12357161028:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d10 with delay 0 [4734:4734:0318/170911.042017:12357161068:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000d10 [4734:4734:0318/170911.042142:12357161192:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1603052231409875050" 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" } } [4734:4734:0318/170911.042201:12357161251:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1603052231409875050" [4734:4734:0318/170911.042249:12357161299:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4734:4734:0318/170911.042295:12357161346:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [4734:4734:0318/170911.042338:12357161388:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b30 with delay 1200000 [4734:4734:0318/170911.042385:12357161439:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4734:4734:0318/170911.042538:12357161589:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4734:4734:0318/170911.042582:12357161635:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [4734:4734:0318/170911.042624:12357161678:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ae0 with delay 0 [4734:4734:0318/170911.042690:12357161740: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 [4734:4734:0318/170911.042743:12357161793:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000ae0 [4734:4734:0318/170911.042820:12357161870:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000009e0 with delay 0 [4734:4734:0318/170911.042864:12357161914:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [4734:4734:0318/170911.042902:12357161953:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b50 with delay 10000 [4734:4734:0318/170911.042941:12357161990:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000009e0 [4734:4734:0318/170911.042974:12357162027:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4734:4734:0318/170911.043036:12357162093:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.043099:12357162153:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000009e0 with delay 0 [4734:4734:0318/170911.043141:12357162192:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000009e0 [4734:4734:0318/170911.043268:12357162318: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" } } [4734:4734:0318/170911.043342:12357162393: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 [4734:4734:0318/170911.043381:12357162436:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [4734:4734:0318/170911.043715:12357162766:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000b50 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [24/28] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [4734:4734:0318/170911.045327:12357164379:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000d90 with delay 0 [4734:4734:0318/170911.045396:12357164446:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4734:4734:0318/170911.045712:12357164764:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0 [4734:4734:0318/170911.045765:12357164815:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000d90 [4734:4734:0318/170911.045807:12357164857:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e70 [4734:4734:0318/170911.045877:12357164927:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4734:4734:0318/170911.045940:12357164991:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f50 with delay 0 [4734:4734:0318/170911.045984:12357165034:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f50 [4734:4734:0318/170911.046025:12357165079:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4734:4734:0318/170911.046066:12357165117:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 0 [4734:4734:0318/170911.046110:12357165160:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e70 [4734:4734:0318/170911.046144:12357165195:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4734:4734:0318/170911.046188:12357165240:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424 [4734:4734:0318/170911.046225:12357165287:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000f50 with delay 0 [4734:4734:0318/170911.046274:12357165324:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000f50 [4734:4734:0318/170911.046345:12357165396:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-9000685672725104912" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4734:4734:0318/170911.046388:12357165438:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424 [4734:4734:0318/170911.046425:12357165484:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e70 with delay 500 [4734:4734:0318/170911.046469:12357165520:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424 [4734:4734:0318/170911.046508:12357165558:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c30 with delay 60000 [4734:4734:0318/170911.046558:12357165610:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e70 [4734:4734:0318/170911.046598:12357165650:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.046650:12357165701:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.046789:12357165839: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: "-9000685672725104912" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4734:4734:0318/170911.046900:12357165951:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e70 with delay 0 [4734:4734:0318/170911.046945:12357166004:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e70 [4734:4734:0318/170911.047077:12357166130:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-9000685672725104912" 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" } } [4734:4734:0318/170911.047136:12357166186:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-9000685672725104912" [4734:4734:0318/170911.047177:12357166227:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4734:4734:0318/170911.047219:12357166275:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [4734:4734:0318/170911.047261:12357166314:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f40 with delay 1200000 [4734:4734:0318/170911.047304:12357166354:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4734:4734:0318/170911.047440:12357166493:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4734:4734:0318/170911.047482:12357166538:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [4734:4734:0318/170911.047529:12357166580:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f50 with delay 0 [4734:4734:0318/170911.047591:12357166646: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 [4734:4734:0318/170911.047643:12357166697:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f50 [4734:4734:0318/170911.047721:12357166774:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000f60 with delay 0 [4734:4734:0318/170911.047769:12357166822:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [4734:4734:0318/170911.047808:12357166858:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000d90 with delay 10000 [4734:4734:0318/170911.047849:12357166899:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000f60 [4734:4734:0318/170911.047883:12357166933:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4734:4734:0318/170911.047940:12357166990:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f60 with delay 0 [4734:4734:0318/170911.047977:12357167027:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000f60 [4734:4734:0318/170911.048029:12357167079:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [4734:4734:0318/170911.048091:12357167144:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9896 with a delay 500000, Now = 211469424 [4734:4734:0318/170911.048130:12357167180:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f50 with delay 500 [4734:4734:0318/170911.048170:12357167221:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9224 with a delay 60000000, Now = 211469424 [4734:4734:0318/170911.048209:12357167259:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000f70 with delay 60000 [4734:4734:0318/170911.048270:12357167321:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f50 [4734:4734:0318/170911.048311:12357167361:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.048358:12357167423:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.048417:12357167476:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4734:4734:0318/170911.048567:12357167618: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 } } } [4734:4734:0318/170911.048652:12357167702:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.048705:12357167756:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000f50 with delay 0 [4734:4734:0318/170911.048748:12357167798:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000f50 [4734:4734:0318/170911.048862:12357167912: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" } } [4734:4734:0318/170911.048941:12357167994: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 [4734:4734:0318/170911.049002:12357168052:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [4734:4734:0318/170911.049102:12357168152:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [4734:4734:0318/170911.049413:12357168464:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000d90 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms) [25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [4734:4734:0318/170911.051073:12357170125:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c20 with delay 0 [4734:4734:0318/170911.051139:12357170190:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4734:4734:0318/170911.051385:12357170437:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0 [4734:4734:0318/170911.051427:12357170489:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c20 [4734:4734:0318/170911.051476:12357170526:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50 [4734:4734:0318/170911.051547:12357170598:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4734:4734:0318/170911.051615:12357170666:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e20 with delay 0 [4734:4734:0318/170911.051664:12357170714:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e20 [4734:4734:0318/170911.051702:12357170752:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4734:4734:0318/170911.051743:12357170794:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 0 [4734:4734:0318/170911.051781:12357170830:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b50 [4734:4734:0318/170911.051815:12357170865:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4734:4734:0318/170911.051861:12357170911:INFO:recurring-task.cc(55)] [Startup] Scheduling 9800 with a delay 0, Now = 210919424 [4734:4734:0318/170911.051899:12357170950:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e20 with delay 0 [4734:4734:0318/170911.051943:12357170993:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e20 [4734:4734:0318/170911.052012:12357171063:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "8208106377270690358" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4734:4734:0318/170911.052058:12357171109:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9608 with a delay 500000, Now = 210919424 [4734:4734:0318/170911.052097:12357171148:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b50 with delay 500 [4734:4734:0318/170911.052135:12357171186:INFO:recurring-task.cc(55)] [Retry] Scheduling 9800 with a delay 60000000, Now = 210919424 [4734:4734:0318/170911.052175:12357171225:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c50 with delay 60000 [4734:4734:0318/170911.052228:12357171284:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50 [4734:4734:0318/170911.052273:12357171323:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.052320:12357171370:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.052465:12357171516: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: "8208106377270690358" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4734:4734:0318/170911.052584:12357171635:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b50 with delay 0 [4734:4734:0318/170911.052626:12357171677:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b50 [4734:4734:0318/170911.052754:12357171804:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "8208106377270690358" 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" } } [4734:4734:0318/170911.052811:12357171862:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "8208106377270690358" [4734:4734:0318/170911.052852:12357171903:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4734:4734:0318/170911.052894:12357171944:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [4734:4734:0318/170911.052933:12357171984:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000ee0 with delay 1200000 [4734:4734:0318/170911.052988:12357172040:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4734:4734:0318/170911.053119:12357172170:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4734:4734:0318/170911.053162:12357172213:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [4734:4734:0318/170911.053199:12357172249:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e20 with delay 0 [4734:4734:0318/170911.053263:12357172314: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 [4734:4734:0318/170911.053311:12357172361:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000e20 [4734:4734:0318/170911.053387:12357172437:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 0 [4734:4734:0318/170911.053444:12357172519:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [4734:4734:0318/170911.053508:12357172559:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c20 with delay 10000 [4734:4734:0318/170911.053544:12357172594:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50 [4734:4734:0318/170911.053578:12357172628:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4734:4734:0318/170911.053636:12357172686:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a50 with delay 0 [4734:4734:0318/170911.053676:12357172727:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a50 [4734:4734:0318/170911.053727:12357172782:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [4734:4734:0318/170911.053792:12357172842:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9608 with a delay 500000, Now = 211469424 [4734:4734:0318/170911.053830:12357172882:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000e20 with delay 500 [4734:4734:0318/170911.053869:12357172919:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9416 with a delay 60000000, Now = 211469424 [4734:4734:0318/170911.053906:12357172957:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000af0 with delay 60000 [4734:4734:0318/170911.053970:12357173026:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000e20 [4734:4734:0318/170911.054020:12357173070:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.054074:12357173125:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.054116:12357173166:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4734:4734:0318/170911.054262:12357173313: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 } } } [4734:4734:0318/170911.054572:12357173626:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c20 [4734:4734:0318/170911.055741:12357174791:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000c50 [4734:4734:0318/170911.055790:12357174840:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x701000000af0 [4734:4734:0318/170911.055850:12357174902: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 [4734:4734:0318/170911.055890:12357174942:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [4734:4734:0318/170911.055971:12357175022: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 } [4734:4734:0318/170911.056015:12357175066:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9608 with a delay 500000, Now = 271469424 [4734:4734:0318/170911.056053:12357175104:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c50 with delay 500 [4734:4734:0318/170911.056091:12357175142:INFO:recurring-task.cc(55)] [Retry] Scheduling 9416 with a delay 60000000, Now = 271469424 [4734:4734:0318/170911.056135:12357175186:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000c20 with delay 60000 [4734:4734:0318/170911.056189:12357175240:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x701000000c50 [4734:4734:0318/170911.056229:12357175288:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.056290:12357175340:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.056328:12357175379:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4734:4734:0318/170911.056494:12357175550: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 [4734:4734:0318/170911.058400:12357177453:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000e30 with delay 0 [4734:4734:0318/170911.058478:12357177528:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4734:4734:0318/170911.058706:12357177758:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0 [4734:4734:0318/170911.058754:12357177807:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000e30 [4734:4734:0318/170911.058796:12357177846:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10 [4734:4734:0318/170911.058866:12357177917:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4734:4734:0318/170911.058927:12357177978:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0 [4734:4734:0318/170911.058970:12357178021:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0 [4734:4734:0318/170911.059006:12357178060:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4734:4734:0318/170911.059049:12357178099:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 0 [4734:4734:0318/170911.059090:12357178140:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b10 [4734:4734:0318/170911.059125:12357178175:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4734:4734:0318/170911.059171:12357178222:INFO:recurring-task.cc(55)] [Startup] Scheduling 10376 with a delay 0, Now = 210919424 [4734:4734:0318/170911.059211:12357178261:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0 [4734:4734:0318/170911.059255:12357178305:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0 [4734:4734:0318/170911.059332:12357178382:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "5319934619187797389" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4734:4734:0318/170911.059376:12357178427:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9992 with a delay 500000, Now = 210919424 [4734:4734:0318/170911.059415:12357178476:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b10 with delay 500 [4734:4734:0318/170911.059462:12357178513:INFO:recurring-task.cc(55)] [Retry] Scheduling 10376 with a delay 60000000, Now = 210919424 [4734:4734:0318/170911.059505:12357178556:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000dd0 with delay 60000 [4734:4734:0318/170911.059556:12357178607:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10 [4734:4734:0318/170911.059593:12357178646:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.059644:12357178694:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.059795:12357178846: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: "5319934619187797389" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4734:4734:0318/170911.059908:12357178959:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b10 with delay 0 [4734:4734:0318/170911.059948:12357179000:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10 [4734:4734:0318/170911.060073:12357179126:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "5319934619187797389" 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" } } [4734:4734:0318/170911.060139:12357179189:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "5319934619187797389" [4734:4734:0318/170911.060180:12357179231:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4734:4734:0318/170911.060222:12357179278:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424 [4734:4734:0318/170911.060264:12357179319:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e20 with delay 1200000 [4734:4734:0318/170911.060308:12357179359:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4734:4734:0318/170911.060447:12357179500:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4734:4734:0318/170911.060489:12357179540:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [4734:4734:0318/170911.060527:12357179578:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0 [4734:4734:0318/170911.060584:12357179634: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 [4734:4734:0318/170911.060631:12357179681:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0 [4734:4734:0318/170911.060707:12357179758:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 0 [4734:4734:0318/170911.060753:12357179810:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [4734:4734:0318/170911.060796:12357179846:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000e30 with delay 10000 [4734:4734:0318/170911.060835:12357179885:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000a50 [4734:4734:0318/170911.060869:12357179920:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4734:4734:0318/170911.060926:12357179977:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.060999:12357180050:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000a50 with delay 0 [4734:4734:0318/170911.061050:12357180101:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000a50 [4734:4734:0318/170911.061151:12357180205: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" } } [4734:4734:0318/170911.061456:12357180507:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000e30 [4734:4734:0318/170911.062505:12357181555: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 [4734:4734:0318/170911.063132:12357182184:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000c90 with delay 0 [4734:4734:0318/170911.063204:12357182263:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4734:4734:0318/170911.063470:12357182521:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 0 [4734:4734:0318/170911.063514:12357182564:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000c90 [4734:4734:0318/170911.063550:12357182600:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b70 [4734:4734:0318/170911.063632:12357182682:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4734:4734:0318/170911.063691:12357182742:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0 [4734:4734:0318/170911.063740:12357182790:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0 [4734:4734:0318/170911.063774:12357182825:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4734:4734:0318/170911.063814:12357182865:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 0 [4734:4734:0318/170911.063859:12357182909:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000b70 [4734:4734:0318/170911.063894:12357182944:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4734:4734:0318/170911.063932:12357182983:INFO:recurring-task.cc(55)] [Startup] Scheduling 9704 with a delay 0, Now = 210919424 [4734:4734:0318/170911.063972:12357183022:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000af0 with delay 0 [4734:4734:0318/170911.064013:12357183063:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000af0 [4734:4734:0318/170911.064085:12357183136:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-4101616717100667104" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4734:4734:0318/170911.064125:12357183181:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424 [4734:4734:0318/170911.064166:12357183216:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000b70 with delay 500 [4734:4734:0318/170911.064205:12357183256:INFO:recurring-task.cc(55)] [Retry] Scheduling 9704 with a delay 60000000, Now = 210919424 [4734:4734:0318/170911.064251:12357183302:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000ac0 with delay 60000 [4734:4734:0318/170911.064303:12357183354:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b70 [4734:4734:0318/170911.064341:12357183391:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.064393:12357183446:INFO:invalidation-client-core.cc(488)] Return client token = "" [4734:4734:0318/170911.064540:12357183591: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: "-4101616717100667104" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4734:4734:0318/170911.064654:12357183705:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b70 with delay 0 [4734:4734:0318/170911.064696:12357183747:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b70 [4734:4734:0318/170911.064826:12357183877:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-4101616717100667104" 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" } } [4734:4734:0318/170911.064888:12357183938:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-4101616717100667104" [4734:4734:0318/170911.064929:12357183981:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4734:4734:0318/170911.064991:12357184042:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424 [4734:4734:0318/170911.065033:12357184084:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000a50 with delay 1200000 [4734:4734:0318/170911.065075:12357184126:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4734:4734:0318/170911.065208:12357184259:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4734:4734:0318/170911.065257:12357184308:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2184 with a delay 0, Now = 211419424 [4734:4734:0318/170911.065298:12357184349:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000af0 with delay 0 [4734:4734:0318/170911.065357:12357184408: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 [4734:4734:0318/170911.065405:12357184456:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000af0 [4734:4734:0318/170911.065484:12357184534:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000b10 with delay 0 [4734:4734:0318/170911.065532:12357184583:INFO:recurring-task.cc(55)] [Retry] Scheduling 2184 with a delay 10000000, Now = 211419424 [4734:4734:0318/170911.065572:12357184622:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000c90 with delay 10000 [4734:4734:0318/170911.065610:12357184660:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000b10 [4734:4734:0318/170911.065644:12357184695:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4734:4734:0318/170911.065926:12357184977:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000c90 [4734:4734:0318/170911.067135:12357186185:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000ac0 [4734:4734:0318/170911.094105:12357213157:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x701000000a50 [4734:4734:0318/170911.094181:12357213232:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4734:4734:0318/170911.094258:12357213311:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4734:4734:0318/170911.094301:12357213352:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [4734:4734:0318/170911.094513:12357213567: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 } [4734:4734:0318/170911.094563:12357213614:INFO:recurring-task.cc(55)] [Send-info] Scheduling 10376 with a delay 500000, Now = 1411419424 [4734:4734:0318/170911.094605:12357213655:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000ac0 with delay 500 [4734:4734:0318/170911.094649:12357213699:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424 [4734:4734:0318/170911.094687:12357213737:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000c90 with delay 1200000 [4734:4734:0318/170911.094742:12357213792:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x701000000ac0 [4734:4734:0318/170911.094779:12357213830:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.094860:12357213911:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4734:4734:0318/170911.094898:12357213949:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4734:4734:0318/170911.095138:12357214189: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 (34 ms) [28/28] InvalidationClientImplTest.Heartbeats (34 ms) SUCCESS: all tests passed. Tests took 1 seconds. 2019-03-18 17:13:43,859 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmpKrt4ao/43ac075953409a10'] 2019-03-18 17:13:43,860 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmpKrt4ao/43ac075953409a10/output.json'] 2019-03-18 17:13:43,860 - root: [INFO] merge_cmd: /b/swarming/w/ir/cache/vpython/ba947a/bin/python /b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --build-properties {"blamelist": ["thakis@chromium.org"], "bot_id": "swarm1908-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:thakis@chromium.org", "created_ts": 1552948098667089, "id": "8918609610450674560", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1401", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1528472/1", "user_agent:git_cl_try"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1401, "category": "git_cl_try", "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "e613f9e78b0f43a2eff084aab079b00b4083ec11", "got_revision_cp": "refs/heads/master@{#641778}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1528472, "patch_project": "chromium/src", "patch_ref": "refs/changes/72/1528472/1", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 1, "patch_storage": "gerrit", "path_config": "generic", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src"} --summary-json /b/swarming/w/ir/tmp/t/tmp1FsB2q.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpKrt4ao -o /b/swarming/w/ir/tmp/t/tmpuEWYtW.json /b/swarming/w/ir/tmp/t/tmpKrt4ao/43ac075953409a10/output.json Running ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"blamelist": ["thakis@chromium.org"], "bot_id": "swarm1908-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:thakis@chromium.org", "created_ts": 1552948098667089, "id": "8918609610450674560", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1401", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1528472/1", "user_agent:git_cl_try"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1401, "category": "git_cl_try", "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "e613f9e78b0f43a2eff084aab079b00b4083ec11", "got_revision_cp": "refs/heads/master@{#641778}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1528472, "patch_project": "chromium/src", "patch_ref": "refs/changes/72/1528472/1", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 1, "patch_storage": "gerrit", "path_config": "generic", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src"}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp1FsB2q.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpKrt4ao', '-o', '/b/swarming/w/ir/tmp/t/tmpuEWYtW.json', '/b/swarming/w/ir/tmp/t/tmpKrt4ao/43ac075953409a10/output.json'] in None (env: None) Command ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"blamelist": ["thakis@chromium.org"], "bot_id": "swarm1908-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:thakis@chromium.org", "created_ts": 1552948098667089, "id": "8918609610450674560", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_msan_rel_ng/1401", "builder:linux_chromium_msan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1528472/1", "user_agent:git_cl_try"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_msan_rel_ng", "buildnumber": 1401, "category": "git_cl_try", "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "e613f9e78b0f43a2eff084aab079b00b4083ec11", "got_revision_cp": "refs/heads/master@{#641778}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1528472, "patch_project": "chromium/src", "patch_ref": "refs/changes/72/1528472/1", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 1, "patch_storage": "gerrit", "path_config": "generic", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src"}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp1FsB2q.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpKrt4ao', '-o', '/b/swarming/w/ir/tmp/t/tmpuEWYtW.json', '/b/swarming/w/ir/tmp/t/tmpKrt4ao/43ac075953409a10/output.json'] returned exit code 0