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

python -u /b/s/w/ir/kitchen-checkout/build/scripts/tools/runit.py --show-path --with-third-party-lib -- python /b/s/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/collect_task.py --verbose -o /b/s/w/ir/tmp/t/tmptMI9MD.json --task-output-dir /b/s/w/ir/tmp/t/tmpc6FkML --merge-script /b/s/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --merge-script-stdout-file /b/s/w/ir/tmp/t/tmp5EDflimerge_script_log --merge-additional-args '[]' --build-properties '{"bot_id": "luci-chromium-ci-trusty-32-15-n6go", "branch": "refs/heads/master", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552959643983899, "id": "8918597504309257904", "project": "chromium", "tags": ["build_address:luci.chromium.ci/ToTLinuxASan/5274", "builder:ToTLinuxASan", "buildset:commit/git/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "gitiles_ref:refs/heads/master", "scheduler_invocation_id:9084027566542148080", "scheduler_job_id:chromium/ToTLinuxASan", "user_agent:luci-scheduler"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "ToTLinuxASan", "buildnumber": 5274, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "got_revision_cp": "refs/heads/master@{#641797}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.clang", "path_config": "generic", "perf_dashboard_machine_group": "ChromiumClang", "recipe": "chromium", "repository": "https://chromium.googlesource.com/chromium/src.git", "revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058"}' --summary-json-file /b/s/w/ir/tmp/t/tmpchCwxq.json -- swarming collect -server https://chromium-swarm.appspot.com -worker 50 -task-summary-python -task-output-stdout all -verbose -requests-json /b/s/w/ir/tmp/t/tmpaeMmHD.json in dir /b/s/w/ir/k: allow_subannotations: True cmd: ['python', '-u', '/b/s/w/ir/kitchen-checkout/build/scripts/tools/runit.py', '--show-path', '--with-third-party-lib', '--', 'python', '/b/s/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/collect_task.py', '--verbose', '-o', '/b/s/w/ir/tmp/t/tmptMI9MD.json', '--task-output-dir', '/b/s/w/ir/tmp/t/tmpc6FkML', '--merge-script', '/b/s/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--merge-script-stdout-file', '/b/s/w/ir/tmp/t/tmp5EDflimerge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"bot_id": "luci-chromium-ci-trusty-32-15-n6go", "branch": "refs/heads/master", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552959643983899, "id": "8918597504309257904", "project": "chromium", "tags": ["build_address:luci.chromium.ci/ToTLinuxASan/5274", "builder:ToTLinuxASan", "buildset:commit/git/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "gitiles_ref:refs/heads/master", "scheduler_invocation_id:9084027566542148080", "scheduler_job_id:chromium/ToTLinuxASan", "user_agent:luci-scheduler"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "ToTLinuxASan", "buildnumber": 5274, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "got_revision_cp": "refs/heads/master@{#641797}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.clang", "path_config": "generic", "perf_dashboard_machine_group": "ChromiumClang", "recipe": "chromium", "repository": "https://chromium.googlesource.com/chromium/src.git", "revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058"}', '--summary-json-file', '/b/s/w/ir/tmp/t/tmpchCwxq.json', '--', 'swarming', 'collect', '-server', 'https://chromium-swarm.appspot.com', '-worker', '50', '-task-summary-python', '-task-output-stdout', 'all', '-verbose', '-requests-json', '/b/s/w/ir/tmp/t/tmpaeMmHD.json'] env: {'CHROME_HEADLESS': '1', 'LLVM_FORCE_HEAD_REVISION': 'YES'} env_prefixes: {'PATH': '/b/s/w/ir/cache/swarming_client'} env_suffixes: {} infra_step: False name_tokens: ('cacheinvalidation_unittests',) ok_ret: frozenset([0]) step_test_data: <lambda>(...) trigger_specs: () full environment: BOTO_CONFIG: /b/s/w/ir/tmp/gsutil_task/.boto BUILDBUCKET_EXPERIMENTAL: FALSE CHROME_HEADLESS: 1 CIPD_CACHE_DIR: /b/s/cipd_cache/cache CIPD_PROTOCOL: v2 DEVSHELL_CLIENT_PORT: 37276 DOCKER_CONFIG: /b/s/w/ir/tmp/docker_cfg_task DOCKER_TMPDIR: /b/s/w/ir/tmp/docker_tmp_task GIT_CONFIG_NOSYSTEM: 1 GIT_TERMINAL_PROMPT: 0 HOME: /home/chrome-bot INFRA_GIT_WRAPPER_HOME: /b/s/w/ir/tmp/git_home_task LLVM_FORCE_HEAD_REVISION: YES LOGDOG_COORDINATOR_HOST: logs.chromium.org LOGDOG_STREAM_PREFIX: buildbucket/cr-buildbucket.appspot.com/8918597504309257904 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/s/w/ir/tmp/ld.sock LOGNAME: chrome-bot LUCI_CONTEXT: /b/s/w/itr1AWBM/luci_context.351859353 MAC_CHROMIUM_TMPDIR: /b/s/w/ir/tmp/t MAIL: /var/mail/chrome-bot NO_GCE_CHECK: False PATH: /b/s/w/ir/cache/swarming_client:/b/s/w/ir/cipd_bin_packages:/b/s/w/ir/cipd_bin_packages/bin:/b/s/cipd_cache/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin PWD: /b/s/w/ir/k PYTHONIOENCODING: UTF-8 PYTHONUNBUFFERED: 1 SHELL: /bin/bash SHLVL: 1 SUDO_COMMAND: /usr/bin/python /b/s/swarming_bot.zip start_bot SUDO_GID: 0 SUDO_UID: 0 SUDO_USER: root SWARMING_BOT_ID: luci-chromium-ci-trusty-32-15-n6go SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 43ac6d2b6c699b11 TEMP: /b/s/w/ir/tmp/t TEMPDIR: /b/s/w/ir/tmp/t TERM: linux TMP: /b/s/w/ir/tmp/t TMPDIR: /b/s/w/ir/tmp/t USER: chrome-bot USERNAME: chrome-bot VPYTHON_VIRTUALENV_ROOT: /b/s/w/ir/cache/vpython _: /b/s/w/ir/cipd_bin_packages/vpython Set PYTHONPATH: /b/s/w/ir/kitchen-checkout/build/scripts:/b/s/w/ir/kitchen-checkout/build/site_config:/b/s/w/ir/kitchen-checkout/build/third_party:/b/s/w/ir/kitchen-checkout/build/third_party/buildbot_8_4p1:/b/s/w/ir/kitchen-checkout/build/third_party/buildbot_slave_8_4:/b/s/w/ir/kitchen-checkout/build/third_party/coverage-3.7.1:/b/s/w/ir/kitchen-checkout/build/third_party/decorator_3_3_1:/b/s/w/ir/kitchen-checkout/build/third_party/google_api_python_client:/b/s/w/ir/kitchen-checkout/build/third_party/httplib2/python2:/b/s/w/ir/kitchen-checkout/build/third_party/infra_libs:/b/s/w/ir/kitchen-checkout/build/third_party/jinja2:/b/s/w/ir/kitchen-checkout/build/third_party/markupsafe:/b/s/w/ir/kitchen-checkout/build/third_party/oauth2client:/b/s/w/ir/kitchen-checkout/build/third_party/pyasn1:/b/s/w/ir/kitchen-checkout/build/third_party/pyasn1-modules:/b/s/w/ir/kitchen-checkout/build/third_party/python-rsa:/b/s/w/ir/kitchen-checkout/build/third_party/requests_2_10_0:/b/s/w/ir/kitchen-checkout/build/third_party/setuptools-0.6c11:/b/s/w/ir/kitchen-checkout/build/third_party/sqlalchemy_0_7_1:/b/s/w/ir/kitchen-checkout/build/third_party/sqlalchemy_migrate_0_7_1:/b/s/w/ir/kitchen-checkout/build/third_party/tempita_0_5:/b/s/w/ir/kitchen-checkout/build/third_party/twisted_10_2:/b/s/w/ir/kitchen-checkout/build/third_party/uritemplate:/b/s/w/ir/kitchen-checkout/build/third_party/site-packages 2019-03-18 23:04:42,982 - root: [DEBUG] Using task_output_dir: '/b/s/w/ir/tmp/t/tmpc6FkML' 2019-03-18 23:04:42,982 - root: [WARNING] task_output_dir '/b/s/w/ir/tmp/t/tmpc6FkML' already exists! 2019-03-18 23:04:42,982 - root: [WARNING] task_output_dir existing content: [] 2019-03-18 23:04:42,982 - 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/s/w/ir/tmp/t/tmpaeMmHD.json -output-dir /b/s/w/ir/tmp/t/tmpc6FkML -task-summary-json /b/s/w/ir/tmp/t/tmpchCwxq.json [D2019-03-18T23:04:42.989611-07:00 28681 0 auth.go:1265] Minting a new token {"key":"luci_ctx/510aebc6a452773476b46ab96db41db3962920703b0bdda77f8777cf4745e65f", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-18T23:04:42.989679-07:00 28681 0 luci_ctx.go:138] POST http://127.0.0.1:46507/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/510aebc6a452773476b46ab96db41db3962920703b0bdda77f8777cf4745e65f", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-18T23:04:42.991898-07:00 28681 0 auth.go:1222] Token expires in 46m14.008240419s {"key":"luci_ctx/510aebc6a452773476b46ab96db41db3962920703b0bdda77f8777cf4745e65f", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 43ad59468db76510: exit 0 Additional test environment: ASAN_OPTIONS=symbolize=0 handle_abort=1 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 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/ioWIyenq/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 [4627:4627:0318/225843.684568:3389149682:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cf0 with delay 0 [4627:4627:0318/225843.684648:3389149763:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cf0 [4627:4627:0318/225843.685068:3389150183: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 } [4627:4627:0318/225843.685128:3389150241:INFO:recurring-task.cc(55)] [Send-info] Scheduling 24232 with a delay 500000, Now = 210919424 [4627:4627:0318/225843.685179:3389150295:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001d10 with delay 500 [4627:4627:0318/225843.685262:3389150374:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001d10 [4627:4627:0318/225843.685353:3389150464:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [4627:4627:0318/225843.685388:3389150511:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (1 ms) [1/28] ProtocolHandlerTest.TokenMissing (1 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [4627:4627:0318/225843.685977:3389151091:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002290 with delay 0 [4627:4627:0318/225843.686033:3389151146:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002290 [4627:4627:0318/225843.686081:3389151195:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 28712 with a delay 500000, Now = 210919424 [4627:4627:0318/225843.686120:3389151231:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000022b0 with delay 500 [4627:4627:0318/225843.686205:3389151316:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000022b0 [4627:4627:0318/225843.686351:3389151469:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [4627:4627:0318/225843.686434:3389151546: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 } [4627:4627:0318/225843.686506:3389151623: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 } } [4627:4627:0318/225843.686675:3389151788: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 } } } [4627:4627:0318/225843.686865:3389151981: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 (2 ms) [2/28] ProtocolHandlerTest.InvalidOutboundMessage (2 ms) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage [4627:4627:0318/225843.687456:3389152570:INFO:protocol-handler.cc(139)] Incoming message: { } [4627:4627:0318/225843.687515:3389152629:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [4627:4627:0318/225843.687555:3389152668:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [3/28] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [ RUN ] RecurringTaskTest.PeriodicTask [4627:4627:0318/225843.687880:3389152994:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -2002972568 with a delay 10000, Now = 0 [4627:4627:0318/225843.687926:3389153041:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002970 with delay 10 [4627:4627:0318/225843.687989:3389153103:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002970 [4627:4627:0318/225843.688042:3389153155:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [4627:4627:0318/225843.688083:3389153195:INFO:recurring-task.cc(55)] [Retry] Scheduling -2002972568 with a delay 60000, Now = 10000 [4627:4627:0318/225843.688119:3389153231:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002990 with delay 60 [4627:4627:0318/225843.688182:3389153295:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x602000002990 [4627:4627:0318/225843.688217:3389153333:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [4627:4627:0318/225843.688256:3389153369:INFO:recurring-task.cc(55)] [Retry] Scheduling -2002972568 with a delay 60000, Now = 70000 [4627:4627:0318/225843.688287:3389153397:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x6020000029b0 with delay 60 [4627:4627:0318/225843.688323:3389153435:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x6020000029b0 [4627:4627:0318/225843.688359:3389153471:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [4627:4627:0318/225843.688392:3389153513:INFO:recurring-task.cc(55)] [Retry] Scheduling -2002972568 with a delay 60000, Now = 130000 [4627:4627:0318/225843.688446:3389153559:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x6020000029d0 with delay 60 [4627:4627:0318/225843.688484:3389153595:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x6020000029d0 [4627:4627:0318/225843.688513:3389153624:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [4627:4627:0318/225843.688544:3389153660:INFO:recurring-task.cc(55)] [Retry] Scheduling -2002972568 with a delay 60000, Now = 190000 [4627:4627:0318/225843.688583:3389153695:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x6020000029f0 with delay 60 [4627:4627:0318/225843.688622:3389153737:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x6020000029f0 [4627:4627:0318/225843.688660:3389153772:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [4627:4627:0318/225843.688694:3389153815:INFO:recurring-task.cc(55)] [Retry] Scheduling -2002972568 with a delay 60000, Now = 250000 [4627:4627:0318/225843.688747:3389153860:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x602000002a10 with delay 60 [4627:4627:0318/225843.688816:3389153927:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x602000002a10 [4627:4627:0318/225843.688849:3389153963:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [4627:4627:0318/225843.688889:3389154006:INFO:recurring-task.cc(55)] [Retry] Scheduling -2002972568 with a delay 60000, Now = 310000 [4627:4627:0318/225843.688928:3389154042:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x602000002a30 with delay 60 [4627:4627:0318/225843.688976:3389154087:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x602000002a30 [4627:4627:0318/225843.689008:3389154121:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [4627:4627:0318/225843.689042:3389154153:INFO:recurring-task.cc(55)] [Retry] Scheduling -2002972568 with a delay 60000, Now = 370000 [4627:4627:0318/225843.689083:3389154200:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x602000002a50 with delay 60 [4627:4627:0318/225843.689130:3389154244:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x602000002a50 [4627:4627:0318/225843.689168:3389154281:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (3 ms) [4/28] RecurringTaskTest.PeriodicTask (3 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [4627:4627:0318/225843.690881:3389155997:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -2003135384 with a delay 10000, Now = 0 [4627:4627:0318/225843.690957:3389156070:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002ad0 with delay 10 [4627:4627:0318/225843.691010:3389156121:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002ad0 [4627:4627:0318/225843.691034:3389156146:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [4627:4627:0318/225843.691079:3389156188:INFO:recurring-task.cc(55)] [Retry] Scheduling -2003135384 with a delay 50000, Now = 10000 [4627:4627:0318/225843.691103:3389156211:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002af0 with delay 50 [4627:4627:0318/225843.691142:3389156250:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x602000002af0 [4627:4627:0318/225843.691165:3389156275:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [4627:4627:0318/225843.691200:3389156309:INFO:recurring-task.cc(55)] [Retry] Scheduling -2003135384 with a delay 149000, Now = 60000 [4627:4627:0318/225843.691237:3389156349:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x602000002b10 with delay 149 [4627:4627:0318/225843.691278:3389156386:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x602000002b10 [4627:4627:0318/225843.691317:3389156426:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [4627:4627:0318/225843.691340:3389156448:INFO:recurring-task.cc(55)] [Retry] Scheduling -2003135384 with a delay 248000, Now = 210000 [4627:4627:0318/225843.691368:3389156478:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x602000002b30 with delay 248 [4627:4627:0318/225843.691406:3389156516:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x602000002b30 [4627:4627:0318/225843.691430:3389156542:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [4627:4627:0318/225843.691464:3389156574:INFO:recurring-task.cc(55)] [Retry] Scheduling -2003135384 with a delay 446000, Now = 460000 [4627:4627:0318/225843.691490:3389156599:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x602000002b50 with delay 446 [4627:4627:0318/225843.691534:3389156641:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x602000002b50 [4627:4627:0318/225843.691555:3389156666:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [4627:4627:0318/225843.691580:3389156687:INFO:recurring-task.cc(55)] [Retry] Scheduling -2003135384 with a delay 842000, Now = 910000 [4627:4627:0318/225843.691601:3389156708:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x602000002b70 with delay 842 [4627:4627:0318/225843.691648:3389156756:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x602000002b70 [4627:4627:0318/225843.691667:3389156774:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [4627:4627:0318/225843.691685:3389156795:INFO:recurring-task.cc(55)] [Retry] Scheduling -2003135384 with a delay 1040000, Now = 1760000 [4627:4627:0318/225843.691716:3389156824:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x602000002b90 with delay 1040 [4627:4627:0318/225843.691759:3389156866:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x602000002b90 [4627:4627:0318/225843.691791:3389156900:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [4627:4627:0318/225843.691814:3389156924:INFO:recurring-task.cc(55)] [Retry] Scheduling -2003135384 with a delay 1040000, Now = 2800000 [4627:4627:0318/225843.691843:3389156952:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x602000002bb0 with delay 1040 [4627:4627:0318/225843.691892:3389157006:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x602000002bb0 [4627:4627:0318/225843.691921:3389157029:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (2 ms) [5/28] RecurringTaskTest.ExponentialBackoffTask (2 ms) [ RUN ] RecurringTaskTest.OneShotTask [4627:4627:0318/225843.692778:3389157903:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -2003165080 with a delay 10000, Now = 0 [4627:4627:0318/225843.692828:3389157936:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002c30 with delay 10 [4627:4627:0318/225843.692864:3389157973:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002c30 [4627:4627:0318/225843.692894:3389158007:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [4627:4627:0318/225843.692927:3389158038:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -2003165080 with a delay 10000, Now = 10000 [4627:4627:0318/225843.692953:3389158062:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002c50 with delay 10 [4627:4627:0318/225843.692993:3389158102:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x602000002c50 [4627:4627:0318/225843.693015:3389158123:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (1 ms) [6/28] RecurringTaskTest.OneShotTask (1 ms) [ RUN ] ThrottleTest.ThrottlingScripted [4627:4627:0318/225843.693956:3389159067:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x602000002cd0 with delay 920 [4627:4627:0318/225843.694009:3389159117:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002cd0 [4627:4627:0318/225843.694257:3389159366:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x602000002cf0 with delay 45000 [4627:4627:0318/225843.695061:3389160171:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002cf0 [ OK ] ThrottleTest.ThrottlingScripted (2 ms) [7/28] ThrottleTest.ThrottlingScripted (2 ms) [ RUN ] ThrottleTest.ThrottlingStorm [4627:4627:0318/225843.695199:3389160311:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002d70 with delay 990 [4627:4627:0318/225843.695267:3389160375:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002d70 [4627:4627:0318/225843.695295:3389160403:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x602000002d90 with delay 1000 [4627:4627:0318/225843.695349:3389160456:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x602000002d90 [4627:4627:0318/225843.695369:3389160476:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x602000002db0 with delay 1000 [4627:4627:0318/225843.695432:3389160540:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x602000002db0 [4627:4627:0318/225843.695454:3389160561:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x602000002dd0 with delay 1000 [4627:4627:0318/225843.695500:3389160608:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x602000002dd0 [4627:4627:0318/225843.695521:3389160632:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x602000002df0 with delay 1000 [4627:4627:0318/225843.695572:3389160680:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x602000002df0 [4627:4627:0318/225843.695606:3389160714:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x602000002e10 with delay 1000 [4627:4627:0318/225843.695656:3389160763:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x602000002e10 [4627:4627:0318/225843.695678:3389160787:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x602000002e30 with delay 54000 [4627:4627:0318/225843.697221:3389162332:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002e30 [4627:4627:0318/225843.697261:3389162371:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x602000002e50 with delay 1000 [4627:4627:0318/225843.697315:3389162422:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x602000002e50 [4627:4627:0318/225843.697337:3389162445:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x602000002e70 with delay 1000 [4627:4627:0318/225843.697386:3389162494:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x602000002e70 [4627:4627:0318/225843.697416:3389162524:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x602000002e90 with delay 1000 [4627:4627:0318/225843.697461:3389162570:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x602000002e90 [4627:4627:0318/225843.697482:3389162591:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x602000002eb0 with delay 1000 [4627:4627:0318/225843.697527:3389162634:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x602000002eb0 [4627:4627:0318/225843.697561:3389162669:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x602000002ed0 with delay 1000 [4627:4627:0318/225843.697610:3389162717:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x602000002ed0 [4627:4627:0318/225843.697628:3389162741:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x602000002ef0 with delay 1000 [4627:4627:0318/225843.697685:3389162793:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x602000002ef0 [4627:4627:0318/225843.697722:3389162829:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x602000002f10 with delay 54000 [4627:4627:0318/225843.699191:3389164301:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x602000002f10 [4627:4627:0318/225843.699231:3389164339:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x602000002f30 with delay 1000 [4627:4627:0318/225843.699278:3389164385:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x602000002f30 [4627:4627:0318/225843.699296:3389164403:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x602000002f50 with delay 1000 [4627:4627:0318/225843.699342:3389164450:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x602000002f50 [4627:4627:0318/225843.699374:3389164482:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x602000002f70 with delay 1000 [4627:4627:0318/225843.699431:3389164541:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x602000002f70 [4627:4627:0318/225843.699456:3389164566:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x602000002f90 with delay 1000 [4627:4627:0318/225843.699502:3389164609:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x602000002f90 [4627:4627:0318/225843.699522:3389164630:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x602000002fb0 with delay 1000 [4627:4627:0318/225843.699567:3389164674:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x602000002fb0 [4627:4627:0318/225843.699586:3389164694:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x602000002fd0 with delay 1000 [4627:4627:0318/225843.699629:3389164736:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x602000002fd0 [4627:4627:0318/225843.699646:3389164753:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x602000002ff0 with delay 54000 [4627:4627:0318/225843.701072:3389166182:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x602000002ff0 [4627:4627:0318/225843.701123:3389166231:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x602000003010 with delay 1000 [4627:4627:0318/225843.701172:3389166282:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x602000003010 [4627:4627:0318/225843.701196:3389166304:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x602000003030 with delay 1000 [4627:4627:0318/225843.701240:3389166348:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x602000003030 [4627:4627:0318/225843.701259:3389166366:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x602000003050 with delay 1000 [4627:4627:0318/225843.701307:3389166414:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x602000003050 [4627:4627:0318/225843.701325:3389166433:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x602000003070 with delay 1000 [4627:4627:0318/225843.701369:3389166479:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x602000003070 [4627:4627:0318/225843.701391:3389166510:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x602000003090 with delay 1000 [4627:4627:0318/225843.701450:3389166558:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x602000003090 [4627:4627:0318/225843.701472:3389166579:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x6020000030b0 with delay 1000 [4627:4627:0318/225843.701515:3389166622:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x6020000030b0 [4627:4627:0318/225843.701547:3389166656:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x6020000030d0 with delay 54000 [4627:4627:0318/225843.703082:3389168197:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x6020000030d0 [4627:4627:0318/225843.703123:3389168231:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x6020000030f0 with delay 1000 [4627:4627:0318/225843.703170:3389168278:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x6020000030f0 [4627:4627:0318/225843.703212:3389168320:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x602000003110 with delay 1000 [4627:4627:0318/225843.703260:3389168367:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x602000003110 [4627:4627:0318/225843.703280:3389168387:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x602000003130 with delay 1000 [4627:4627:0318/225843.703323:3389168430:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x602000003130 [4627:4627:0318/225843.703340:3389168447:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x602000003150 with delay 1000 [4627:4627:0318/225843.703385:3389168492:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x602000003150 [4627:4627:0318/225843.703413:3389168521:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x602000003170 with delay 1000 [4627:4627:0318/225843.703457:3389168565:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x602000003170 [4627:4627:0318/225843.703475:3389168582:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x602000003190 with delay 1000 [4627:4627:0318/225843.703531:3389168644:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x602000003190 [4627:4627:0318/225843.703577:3389168685:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x6020000031b0 with delay 54000 [4627:4627:0318/225843.705083:3389170193:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x6020000031b0 [ OK ] ThrottleTest.ThrottlingStorm (10 ms) [8/28] ThrottleTest.ThrottlingStorm (10 ms) [ RUN ] ProtocolHandlerTest.SendInitializeOnly [4626:4626:0318/225843.681630:3389146748:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cf0 with delay 0 [4626:4626:0318/225843.682033:3389147147:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cf0 [4626:4626:0318/225843.682443:3389147563: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 } [4626:4626:0318/225843.682528:3389147642:INFO:recurring-task.cc(55)] [Startup] Scheduling 24232 with a delay 500000, Now = 210919424 [4626:4626:0318/225843.682587:3389147700:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e90 with delay 500 [4626:4626:0318/225843.682665:3389147780:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001e90 [4626:4626:0318/225843.683059:3389148173:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "unit-test-nonce" application_client_id: { client_type: 2 client_name: "unit-test-client-id" } digest_serialization_type: BYTE_BASED } } [ OK ] ProtocolHandlerTest.SendInitializeOnly (3 ms) [9/28] ProtocolHandlerTest.SendInitializeOnly (3 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [4626:4626:0318/225843.684559:3389149673:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "fake nonce" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } [ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (0 ms) [10/28] ProtocolHandlerTest.ReceiveTokenControlOnly (0 ms) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes [4626:4626:0318/225843.685184:3389150299:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002ad0 with delay 0 [4626:4626:0318/225843.685296:3389150409:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002af0 with delay 0 [4626:4626:0318/225843.685344:3389150461:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b10 with delay 0 [4626:4626:0318/225843.685413:3389150543:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b30 with delay 0 [4626:4626:0318/225843.685478:3389150590:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b50 with delay 0 [4626:4626:0318/225843.685523:3389150635:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b70 with delay 0 [4626:4626:0318/225843.685968:3389151083:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002ad0 [4626:4626:0318/225843.686144:3389151263: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 } [4626:4626:0318/225843.686218:3389151331:INFO:recurring-task.cc(55)] [Send-info] Scheduling 35240 with a delay 500000, Now = 210919424 [4626:4626:0318/225843.686282:3389151394:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002d10 with delay 500 [4626:4626:0318/225843.686320:3389151432:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002af0 [4626:4626:0318/225843.686360:3389151474:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b10 [4626:4626:0318/225843.686395:3389151511:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b30 [4626:4626:0318/225843.686452:3389151564:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b50 [4626:4626:0318/225843.686513:3389151625:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b70 [4626:4626:0318/225843.686573:3389151683:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [4626:4626:0318/225843.686667:3389151780:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002d10 [4626:4626:0318/225843.686883:3389152022:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [4626:4626:0318/225843.687467:3389152582: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 [4626:4626:0318/225843.689736:3389154849: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 (2 ms) [12/28] ProtocolHandlerTest.IncomingCompositeMessage (2 ms) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage [4626:4626:0318/225843.690482:3389155595: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 } } [4626:4626:0318/225843.690584:3389155701: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" } [4626:4626:0318/225843.690711:3389155844: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 } } [4626:4626:0318/225843.690866:3389155979: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 [4626:4626:0318/225843.691978:3389157102: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 } } [4626:4626:0318/225843.692207:3389157324: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 [4626:4626:0318/225843.693020:3389158140: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 (1 ms) [15/28] ProtocolHandlerTest.MinorVersionMismatch (1 ms) [ RUN ] ProtocolHandlerTest.ConfigMessage [4626:4626:0318/225843.693837:3389158953: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" } } [4626:4626:0318/225843.693925:3389159038:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004850 with delay 0 [4626:4626:0318/225843.693971:3389159090:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004850 [4626:4626:0318/225843.694137:3389159253: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 } [4626:4626:0318/225843.694211:3389159327:INFO:recurring-task.cc(55)] [Send-info] Scheduling 64296 with a delay 500000, Now = 210919424 [4626:4626:0318/225843.694262:3389159375:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004870 with delay 500 [4626:4626:0318/225843.694375:3389159488:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004870 [4626:4626:0318/225843.694424:3389159541:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 [ OK ] ProtocolHandlerTest.ConfigMessage (39 ms) [16/28] ProtocolHandlerTest.ConfigMessage (39 ms) [ RUN ] ProtocolHandlerTest.ErrorMessage [4626:4626:0318/225843.732737:3389197850: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 [4626:4626:0318/225843.733234:3389198344: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 [4624:4624:0318/225843.673720:3389138838:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002030 with delay 0 [4624:4624:0318/225843.674052:3389139161:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4624:4624:0318/225843.674272:3389139381:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002550 with delay 0 [4624:4624:0318/225843.674308:3389139418:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002030 [4624:4624:0318/225843.674342:3389139457:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002550 [4624:4624:0318/225843.674405:3389139513:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4624:4624:0318/225843.674456:3389139566:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002610 with delay 0 [4624:4624:0318/225843.674503:3389139614:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002610 [4624:4624:0318/225843.674528:3389139635:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4624:4624:0318/225843.674565:3389139676:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002650 with delay 0 [4624:4624:0318/225843.674597:3389139708:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002650 [4624:4624:0318/225843.674625:3389139735:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4624:4624:0318/225843.674660:3389139769:INFO:recurring-task.cc(55)] [Startup] Scheduling 24488 with a delay 0, Now = 210919424 [4624:4624:0318/225843.674693:3389139802:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002670 with delay 0 [4624:4624:0318/225843.674720:3389139830:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002670 [4624:4624:0318/225843.674796:3389139907:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-8707204671020369814" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4624:4624:0318/225843.674830:3389139939:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 24744 with a delay 500000, Now = 210919424 [4624:4624:0318/225843.674857:3389139965:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002690 with delay 500 [4624:4624:0318/225843.674884:3389139992:INFO:recurring-task.cc(55)] [Retry] Scheduling 24488 with a delay 60000000, Now = 210919424 [4624:4624:0318/225843.674926:3389140036:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000026b0 with delay 60000 [4624:4624:0318/225843.675003:3389140111:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002690 [4624:4624:0318/225843.675036:3389140148:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.675100:3389140209:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.675234:3389140343: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: "-8707204671020369814" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4624:4624:0318/225843.675389:3389140499:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002750 with delay 0 [4624:4624:0318/225843.675421:3389140530:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002750 [4624:4624:0318/225843.675564:3389140674:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-8707204671020369814" 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" } } [4624:4624:0318/225843.675619:3389140727:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-8707204671020369814" [4624:4624:0318/225843.675651:3389140761:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4624:4624:0318/225843.675686:3389140796:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 13096 with a delay 1200000000, Now = 211419424 [4624:4624:0318/225843.675724:3389140837:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002770 with delay 1200000 [4624:4624:0318/225843.675769:3389140881:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4624:4624:0318/225843.675920:3389141029:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4624:4624:0318/225843.675954:3389141066:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 9672 with a delay 0, Now = 211419424 [4624:4624:0318/225843.675987:3389141098:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002990 with delay 0 [4624:4624:0318/225843.676039:3389141148: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 [4624:4624:0318/225843.676091:3389141202:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002990 [4624:4624:0318/225843.676183:3389141291:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a50 with delay 0 [4624:4624:0318/225843.676218:3389141328:INFO:recurring-task.cc(55)] [Retry] Scheduling 9672 with a delay 10000000, Now = 211419424 [4624:4624:0318/225843.676245:3389141353:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a90 with delay 10000 [4624:4624:0318/225843.676278:3389141388:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002a50 [4624:4624:0318/225843.676301:3389141411:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (3 ms) [19/28] InvalidationClientImplTest.Start (3 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [4624:4624:0318/225843.676939:3389142049:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000032f0 with delay 0 [4624:4624:0318/225843.676989:3389142100: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 [4624:4624:0318/225843.677429:3389142547:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003b90 with delay 0 [4624:4624:0318/225843.677480:3389142588:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4624:4624:0318/225843.677739:3389142849:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000041f0 with delay 0 [4624:4624:0318/225843.677775:3389142898:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003b90 [4624:4624:0318/225843.677827:3389142935:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000041f0 [4624:4624:0318/225843.677875:3389142983:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4624:4624:0318/225843.677937:3389143050:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000042b0 with delay 0 [4624:4624:0318/225843.677974:3389143083:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000042b0 [4624:4624:0318/225843.677995:3389143106:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4624:4624:0318/225843.678025:3389143133:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000042f0 with delay 0 [4624:4624:0318/225843.678057:3389143166:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000042f0 [4624:4624:0318/225843.678085:3389143194:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4624:4624:0318/225843.678114:3389143228:INFO:recurring-task.cc(55)] [Startup] Scheduling 45608 with a delay 0, Now = 210919424 [4624:4624:0318/225843.678152:3389143262:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004310 with delay 0 [4624:4624:0318/225843.678184:3389143298:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004310 [4624:4624:0318/225843.678241:3389143352:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-5463768537694314990" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4624:4624:0318/225843.678286:3389143395:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 45864 with a delay 500000, Now = 210919424 [4624:4624:0318/225843.678315:3389143425:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004330 with delay 500 [4624:4624:0318/225843.678346:3389143454:INFO:recurring-task.cc(55)] [Retry] Scheduling 45608 with a delay 60000000, Now = 210919424 [4624:4624:0318/225843.678389:3389143500:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004350 with delay 60000 [4624:4624:0318/225843.678471:3389143581:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004330 [4624:4624:0318/225843.678496:3389143608:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.678547:3389143656:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.678674:3389143788: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: "-5463768537694314990" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4624:4624:0318/225843.678815:3389143924:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000043f0 with delay 0 [4624:4624:0318/225843.678845:3389143954:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000043f0 [4624:4624:0318/225843.678974:3389144086:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-5463768537694314990" 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" } } [4624:4624:0318/225843.679042:3389144153:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-5463768537694314990" [4624:4624:0318/225843.679080:3389144193:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4624:4624:0318/225843.679119:3389144228:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 15560 with a delay 1200000000, Now = 211419424 [4624:4624:0318/225843.679149:3389144259:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004410 with delay 1200000 [4624:4624:0318/225843.679180:3389144292:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4624:4624:0318/225843.679310:3389144424:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4624:4624:0318/225843.679347:3389144459:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 13896 with a delay 0, Now = 211419424 [4624:4624:0318/225843.679382:3389144493:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004630 with delay 0 [4624:4624:0318/225843.679447:3389144558: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 [4624:4624:0318/225843.679498:3389144609:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004630 [4624:4624:0318/225843.679564:3389144675:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000046f0 with delay 0 [4624:4624:0318/225843.679603:3389144713:INFO:recurring-task.cc(55)] [Retry] Scheduling 13896 with a delay 10000000, Now = 211419424 [4624:4624:0318/225843.679637:3389144750:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004730 with delay 10000 [4624:4624:0318/225843.679667:3389144777:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000046f0 [4624:4624:0318/225843.679689:3389144802:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4624:4624:0318/225843.679757:3389144875:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004750 with delay 0 [4624:4624:0318/225843.679803:3389144913:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000004750 [4624:4624:0318/225843.679847:3389144958:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [4624:4624:0318/225843.679888:3389144997:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [4624:4624:0318/225843.679917:3389145028:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [4624:4624:0318/225843.679988:3389145097:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 45864 with a delay 500000, Now = 211469424 [4624:4624:0318/225843.680015:3389145123:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004770 with delay 500 [4624:4624:0318/225843.680042:3389145150:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 45736 with a delay 60000000, Now = 211469424 [4624:4624:0318/225843.680078:3389145192:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004790 with delay 60000 [4624:4624:0318/225843.680176:3389145288:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000004770 [4624:4624:0318/225843.680208:3389145316:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.680256:3389145375:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.680299:3389145407:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4624:4624:0318/225843.680439:3389145548: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 } } } [4624:4624:0318/225843.680520:3389145632:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.680594:3389145704:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000004830 with delay 0 [4624:4624:0318/225843.680626:3389145739:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000004830 [4624:4624:0318/225843.680852:3389145962: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 } } } } [4624:4624:0318/225843.680947:3389146057: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 [4624:4624:0318/225843.681023:3389146135:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [4624:4624:0318/225843.681111:3389146220:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [4624:4624:0318/225843.681177:3389146286:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [4624:4624:0318/225843.681555:3389146665:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000004730 [ OK ] InvalidationClientImplTest.Register (5 ms) [21/28] InvalidationClientImplTest.Register (5 ms) [ RUN ] InvalidationClientImplTest.Invalidations [4624:4624:0318/225843.682928:3389148040:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005410 with delay 0 [4624:4624:0318/225843.682986:3389148095:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4624:4624:0318/225843.683258:3389148375:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005af0 with delay 0 [4624:4624:0318/225843.683298:3389148406:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005410 [4624:4624:0318/225843.683323:3389148431:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005af0 [4624:4624:0318/225843.683397:3389148506:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4624:4624:0318/225843.683455:3389148565:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005bb0 with delay 0 [4624:4624:0318/225843.683486:3389148593:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005bb0 [4624:4624:0318/225843.683505:3389148614:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4624:4624:0318/225843.683532:3389148641:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005bf0 with delay 0 [4624:4624:0318/225843.683559:3389148670:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005bf0 [4624:4624:0318/225843.683591:3389148700:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4624:4624:0318/225843.683625:3389148734:INFO:recurring-task.cc(55)] [Startup] Scheduling 73000 with a delay 0, Now = 210919424 [4624:4624:0318/225843.683656:3389148767:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c10 with delay 0 [4624:4624:0318/225843.683687:3389148794:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005c10 [4624:4624:0318/225843.683736:3389148846:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "604660342583291883" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4624:4624:0318/225843.683789:3389148900:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 73256 with a delay 500000, Now = 210919424 [4624:4624:0318/225843.683820:3389148930:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c30 with delay 500 [4624:4624:0318/225843.683852:3389148960:INFO:recurring-task.cc(55)] [Retry] Scheduling 73000 with a delay 60000000, Now = 210919424 [4624:4624:0318/225843.683875:3389148983:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c50 with delay 60000 [4624:4624:0318/225843.683910:3389149019:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005c30 [4624:4624:0318/225843.683935:3389149045:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.683981:3389149092:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.684086:3389149196: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: "604660342583291883" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4624:4624:0318/225843.684176:3389149286:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005cf0 with delay 0 [4624:4624:0318/225843.684203:3389149311:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005cf0 [4624:4624:0318/225843.684335:3389149444:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "604660342583291883" 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" } } [4624:4624:0318/225843.684383:3389149493:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "604660342583291883" [4624:4624:0318/225843.684412:3389149520:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4624:4624:0318/225843.684444:3389149554:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 20840 with a delay 1200000000, Now = 211419424 [4624:4624:0318/225843.684472:3389149581:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005d10 with delay 1200000 [4624:4624:0318/225843.684514:3389149623:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4624:4624:0318/225843.684634:3389149746:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4624:4624:0318/225843.684666:3389149774:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 20616 with a delay 0, Now = 211419424 [4624:4624:0318/225843.684693:3389149801:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005f30 with delay 0 [4624:4624:0318/225843.684745:3389149855: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 [4624:4624:0318/225843.684796:3389149906:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005f30 [4624:4624:0318/225843.684861:3389149971:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005ff0 with delay 0 [4624:4624:0318/225843.684903:3389150011:INFO:recurring-task.cc(55)] [Retry] Scheduling 20616 with a delay 10000000, Now = 211419424 [4624:4624:0318/225843.684958:3389150068:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000006030 with delay 10000 [4624:4624:0318/225843.684986:3389150093:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005ff0 [4624:4624:0318/225843.685006:3389150114:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4624:4624:0318/225843.685048:3389150157:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.685095:3389150207:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000006050 with delay 0 [4624:4624:0318/225843.685122:3389150231:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000006050 [4624:4624:0318/225843.685306:3389150422: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 } } } [4624:4624:0318/225843.685392:3389150502: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 [4624:4624:0318/225843.685471:3389150581: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" } [4624:4624:0318/225843.685585:3389150694:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [4624:4624:0318/225843.685651:3389150759:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [4624:4624:0318/225843.685714:3389150823:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006430 with delay 0 [4624:4624:0318/225843.685740:3389150848:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006450 with delay 0 [4624:4624:0318/225843.685770:3389150878:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006470 with delay 0 [4624:4624:0318/225843.685803:3389150915:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006430 [4624:4624:0318/225843.685846:3389150956:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 73256 with a delay 500000, Now = 211519424 [4624:4624:0318/225843.685873:3389150980:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006490 with delay 500 [4624:4624:0318/225843.685900:3389151010:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006450 [4624:4624:0318/225843.685927:3389151037:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006470 [4624:4624:0318/225843.685978:3389151088:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x602000006490 [4624:4624:0318/225843.686024:3389151134:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.686069:3389151178:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.686101:3389151211:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4624:4624:0318/225843.686270:3389151379: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 (4 ms) [22/28] InvalidationClientImplTest.Invalidations (4 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [4624:4624:0318/225843.686948:3389152059:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006d70 with delay 0 [4624:4624:0318/225843.687002:3389152113:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4624:4624:0318/225843.687206:3389152316:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007290 with delay 0 [4624:4624:0318/225843.687235:3389152344:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006d70 [4624:4624:0318/225843.687274:3389152383:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007290 [4624:4624:0318/225843.687320:3389152429:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4624:4624:0318/225843.687374:3389152484:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007350 with delay 0 [4624:4624:0318/225843.687408:3389152521:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007350 [4624:4624:0318/225843.687443:3389152552:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4624:4624:0318/225843.687471:3389152580:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007390 with delay 0 [4624:4624:0318/225843.687497:3389152605:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007390 [4624:4624:0318/225843.687517:3389152626:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4624:4624:0318/225843.687544:3389152653:INFO:recurring-task.cc(55)] [Startup] Scheduling 98728 with a delay 0, Now = 210919424 [4624:4624:0318/225843.687571:3389152681:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073b0 with delay 0 [4624:4624:0318/225843.687598:3389152706:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000073b0 [4624:4624:0318/225843.687649:3389152758:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "3199200971797718727" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4624:4624:0318/225843.687676:3389152785:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 98984 with a delay 500000, Now = 210919424 [4624:4624:0318/225843.687706:3389152815:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073d0 with delay 500 [4624:4624:0318/225843.687735:3389152844:INFO:recurring-task.cc(55)] [Retry] Scheduling 98728 with a delay 60000000, Now = 210919424 [4624:4624:0318/225843.687760:3389152871:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073f0 with delay 60000 [4624:4624:0318/225843.687821:3389152931:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000073d0 [4624:4624:0318/225843.687853:3389152964:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.687896:3389153008:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.688022:3389153133: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: "3199200971797718727" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4624:4624:0318/225843.688124:3389153233:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007490 with delay 0 [4624:4624:0318/225843.688165:3389153275:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007490 [4624:4624:0318/225843.688277:3389153386:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "3199200971797718727" 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" } } [4624:4624:0318/225843.688325:3389153435:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "3199200971797718727" [4624:4624:0318/225843.688352:3389153462:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4624:4624:0318/225843.688389:3389153499:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 25064 with a delay 1200000000, Now = 211419424 [4624:4624:0318/225843.688418:3389153529:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000074b0 with delay 1200000 [4624:4624:0318/225843.688450:3389153559:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4624:4624:0318/225843.688577:3389153686:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4624:4624:0318/225843.688616:3389153725:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 26760 with a delay 0, Now = 211419424 [4624:4624:0318/225843.688655:3389153764:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000076d0 with delay 0 [4624:4624:0318/225843.688698:3389153808: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 [4624:4624:0318/225843.688734:3389153842:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000076d0 [4624:4624:0318/225843.688815:3389153924:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007790 with delay 0 [4624:4624:0318/225843.688851:3389153960:INFO:recurring-task.cc(55)] [Retry] Scheduling 26760 with a delay 10000000, Now = 211419424 [4624:4624:0318/225843.688881:3389153990:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000077d0 with delay 10000 [4624:4624:0318/225843.688907:3389154017:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007790 [4624:4624:0318/225843.688943:3389154052:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4624:4624:0318/225843.688993:3389154103:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.689036:3389154144:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000077f0 with delay 0 [4624:4624:0318/225843.689067:3389154176:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x6020000077f0 [4624:4624:0318/225843.689181:3389154291: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 } } [4624:4624:0318/225843.689242:3389154352: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 [4624:4624:0318/225843.689285:3389154393:INFO:protocol-handler.cc(294)] Adding subtree: { } [4624:4624:0318/225843.689312:3389154423:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 98984 with a delay 500000, Now = 211469424 [4624:4624:0318/225843.689357:3389154466:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000007810 with delay 500 [4624:4624:0318/225843.689387:3389154496:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [4624:4624:0318/225843.689563:3389154679: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 } [4624:4624:0318/225843.689632:3389154740:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000007810 [4624:4624:0318/225843.689659:3389154768:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.689724:3389154833:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.689751:3389154861:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4624:4624:0318/225843.690069:3389155180: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 } } [4624:4624:0318/225843.690344:3389155454:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x6020000077d0 [ OK ] InvalidationClientImplTest.ServerRequests (5 ms) [23/28] InvalidationClientImplTest.ServerRequests (5 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [4624:4624:0318/225843.691644:3389156755:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000080f0 with delay 0 [4624:4624:0318/225843.691694:3389156804:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4624:4624:0318/225843.691921:3389157031:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000086b0 with delay 0 [4624:4624:0318/225843.691953:3389157061:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000080f0 [4624:4624:0318/225843.691980:3389157089:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000086b0 [4624:4624:0318/225843.692028:3389157137:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4624:4624:0318/225843.692076:3389157184:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008770 with delay 0 [4624:4624:0318/225843.692111:3389157221:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008770 [4624:4624:0318/225843.692142:3389157251:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4624:4624:0318/225843.692166:3389157273:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087b0 with delay 0 [4624:4624:0318/225843.692190:3389157299:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087b0 [4624:4624:0318/225843.692211:3389157318:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4624:4624:0318/225843.692252:3389157362:INFO:recurring-task.cc(55)] [Startup] Scheduling 122792 with a delay 0, Now = 210919424 [4624:4624:0318/225843.692291:3389157402:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087d0 with delay 0 [4624:4624:0318/225843.692321:3389157431:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087d0 [4624:4624:0318/225843.692371:3389157480:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-1932575757980618374" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4624:4624:0318/225843.692401:3389157510:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 123048 with a delay 500000, Now = 210919424 [4624:4624:0318/225843.692427:3389157537:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087f0 with delay 500 [4624:4624:0318/225843.692455:3389157563:INFO:recurring-task.cc(55)] [Retry] Scheduling 122792 with a delay 60000000, Now = 210919424 [4624:4624:0318/225843.692478:3389157587:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008810 with delay 60000 [4624:4624:0318/225843.692515:3389157622:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000087f0 [4624:4624:0318/225843.692539:3389157650:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.692576:3389157685:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.692690:3389157801: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: "-1932575757980618374" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4624:4624:0318/225843.692798:3389157907:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000088b0 with delay 0 [4624:4624:0318/225843.692831:3389157941:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000088b0 [4624:4624:0318/225843.692958:3389158067:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-1932575757980618374" 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" } } [4624:4624:0318/225843.693007:3389158117:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-1932575757980618374" [4624:4624:0318/225843.693043:3389158152:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4624:4624:0318/225843.693071:3389158180:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 28584 with a delay 1200000000, Now = 211419424 [4624:4624:0318/225843.693102:3389158211:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000088d0 with delay 1200000 [4624:4624:0318/225843.693131:3389158242:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4624:4624:0318/225843.693244:3389158354:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4624:4624:0318/225843.693278:3389158387:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 32136 with a delay 0, Now = 211419424 [4624:4624:0318/225843.693320:3389158430:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008af0 with delay 0 [4624:4624:0318/225843.693380:3389158490: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 [4624:4624:0318/225843.693418:3389158527:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008af0 [4624:4624:0318/225843.693471:3389158580:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008bb0 with delay 0 [4624:4624:0318/225843.693510:3389158619:INFO:recurring-task.cc(55)] [Retry] Scheduling 32136 with a delay 10000000, Now = 211419424 [4624:4624:0318/225843.693536:3389158644:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008bf0 with delay 10000 [4624:4624:0318/225843.693559:3389158668:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008bb0 [4624:4624:0318/225843.693579:3389158688:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4624:4624:0318/225843.693618:3389158727:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.693656:3389158765:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000008c10 with delay 0 [4624:4624:0318/225843.693679:3389158789:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000008c10 [4624:4624:0318/225843.693775:3389158896: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" } } [4624:4624:0318/225843.693855:3389158964: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 [4624:4624:0318/225843.693886:3389158994:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [4624:4624:0318/225843.694122:3389159232:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000008bf0 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [24/28] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [4624:4624:0318/225843.695350:3389160462:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009570 with delay 0 [4624:4624:0318/225843.695407:3389160518:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4624:4624:0318/225843.695657:3389160766:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009bf0 with delay 0 [4624:4624:0318/225843.695690:3389160798:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009570 [4624:4624:0318/225843.695713:3389160822:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009bf0 [4624:4624:0318/225843.695766:3389160876:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4624:4624:0318/225843.695824:3389160934:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009cb0 with delay 0 [4624:4624:0318/225843.695856:3389160965:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009cb0 [4624:4624:0318/225843.695878:3389160987:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4624:4624:0318/225843.695905:3389161013:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009cf0 with delay 0 [4624:4624:0318/225843.695948:3389161057:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009cf0 [4624:4624:0318/225843.695971:3389161080:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4624:4624:0318/225843.696007:3389161118:INFO:recurring-task.cc(55)] [Startup] Scheduling 142376 with a delay 0, Now = 210919424 [4624:4624:0318/225843.696037:3389161146:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d10 with delay 0 [4624:4624:0318/225843.696073:3389161184:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009d10 [4624:4624:0318/225843.696132:3389161245:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-4577745654686934527" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4624:4624:0318/225843.696166:3389161275:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 142632 with a delay 500000, Now = 210919424 [4624:4624:0318/225843.696197:3389161305:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d30 with delay 500 [4624:4624:0318/225843.696220:3389161332:INFO:recurring-task.cc(55)] [Retry] Scheduling 142376 with a delay 60000000, Now = 210919424 [4624:4624:0318/225843.696248:3389161356:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d50 with delay 60000 [4624:4624:0318/225843.696291:3389161398:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009d30 [4624:4624:0318/225843.696312:3389161422:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.696387:3389161501:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.696498:3389161612: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: "-4577745654686934527" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4624:4624:0318/225843.696612:3389161725:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009df0 with delay 0 [4624:4624:0318/225843.696662:3389161771:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009df0 [4624:4624:0318/225843.696792:3389161902:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-4577745654686934527" 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" } } [4624:4624:0318/225843.696845:3389161954:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-4577745654686934527" [4624:4624:0318/225843.696875:3389161985:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4624:4624:0318/225843.696914:3389162024:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 31928 with a delay 1200000000, Now = 211419424 [4624:4624:0318/225843.696942:3389162050:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009e10 with delay 1200000 [4624:4624:0318/225843.696967:3389162077:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4624:4624:0318/225843.697088:3389162198:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4624:4624:0318/225843.697125:3389162234:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 35592 with a delay 0, Now = 211419424 [4624:4624:0318/225843.697161:3389162270:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a030 with delay 0 [4624:4624:0318/225843.697201:3389162309: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 [4624:4624:0318/225843.697248:3389162357:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a030 [4624:4624:0318/225843.697314:3389162423:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a0f0 with delay 0 [4624:4624:0318/225843.697346:3389162456:INFO:recurring-task.cc(55)] [Retry] Scheduling 35592 with a delay 10000000, Now = 211419424 [4624:4624:0318/225843.697373:3389162482:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a130 with delay 10000 [4624:4624:0318/225843.697399:3389162507:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a0f0 [4624:4624:0318/225843.697419:3389162527:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4624:4624:0318/225843.697458:3389162567:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a150 with delay 0 [4624:4624:0318/225843.697485:3389162602:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000a150 [4624:4624:0318/225843.697537:3389162645:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [4624:4624:0318/225843.697589:3389162699:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 142632 with a delay 500000, Now = 211469424 [4624:4624:0318/225843.697615:3389162726:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a170 with delay 500 [4624:4624:0318/225843.697643:3389162752:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 142504 with a delay 60000000, Now = 211469424 [4624:4624:0318/225843.697677:3389162787:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a190 with delay 60000 [4624:4624:0318/225843.697719:3389162828:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000a170 [4624:4624:0318/225843.697745:3389162855:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.697809:3389162918:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.697834:3389162942:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4624:4624:0318/225843.697946:3389163056: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 } } } [4624:4624:0318/225843.698027:3389163136:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.698066:3389163174:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x60200000a230 with delay 0 [4624:4624:0318/225843.698090:3389163199:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000a230 [4624:4624:0318/225843.698180:3389163289: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" } } [4624:4624:0318/225843.698247:3389163357: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 [4624:4624:0318/225843.698285:3389163394:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [4624:4624:0318/225843.698375:3389163485:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [4624:4624:0318/225843.698631:3389163742:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000a130 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (4 ms) [25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (4 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [4624:4624:0318/225843.699937:3389165049:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ac90 with delay 0 [4624:4624:0318/225843.699993:3389165102:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4624:4624:0318/225843.700197:3389165306:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b1b0 with delay 0 [4624:4624:0318/225843.700228:3389165337:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000ac90 [4624:4624:0318/225843.700252:3389165372:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b1b0 [4624:4624:0318/225843.700308:3389165416:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4624:4624:0318/225843.700353:3389165463:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b270 with delay 0 [4624:4624:0318/225843.700383:3389165493:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b270 [4624:4624:0318/225843.700404:3389165513:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4624:4624:0318/225843.700430:3389165540:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2b0 with delay 0 [4624:4624:0318/225843.700454:3389165563:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b2b0 [4624:4624:0318/225843.700476:3389165587:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4624:4624:0318/225843.700503:3389165613:INFO:recurring-task.cc(55)] [Startup] Scheduling 167080 with a delay 0, Now = 210919424 [4624:4624:0318/225843.700529:3389165636:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2d0 with delay 0 [4624:4624:0318/225843.700564:3389165674:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b2d0 [4624:4624:0318/225843.700628:3389165737:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-1337787145889830885" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4624:4624:0318/225843.700668:3389165777:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 167336 with a delay 500000, Now = 210919424 [4624:4624:0318/225843.700696:3389165805:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2f0 with delay 500 [4624:4624:0318/225843.700719:3389165830:INFO:recurring-task.cc(55)] [Retry] Scheduling 167080 with a delay 60000000, Now = 210919424 [4624:4624:0318/225843.700746:3389165855:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b310 with delay 60000 [4624:4624:0318/225843.700794:3389165903:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b2f0 [4624:4624:0318/225843.700843:3389165952:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.700880:3389165988:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.700983:3389166094: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: "-1337787145889830885" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4624:4624:0318/225843.701081:3389166191:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b3b0 with delay 0 [4624:4624:0318/225843.701116:3389166226:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b3b0 [4624:4624:0318/225843.701224:3389166334:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-1337787145889830885" 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" } } [4624:4624:0318/225843.701275:3389166384:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-1337787145889830885" [4624:4624:0318/225843.701307:3389166416:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4624:4624:0318/225843.701350:3389166458:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 35448 with a delay 1200000000, Now = 211419424 [4624:4624:0318/225843.701376:3389166489:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b3d0 with delay 1200000 [4624:4624:0318/225843.701406:3389166516:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4624:4624:0318/225843.701519:3389166628:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4624:4624:0318/225843.701551:3389166660:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 40968 with a delay 0, Now = 211419424 [4624:4624:0318/225843.701579:3389166689:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b5f0 with delay 0 [4624:4624:0318/225843.701619:3389166728: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 [4624:4624:0318/225843.701652:3389166762:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b5f0 [4624:4624:0318/225843.701710:3389166820:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b6b0 with delay 0 [4624:4624:0318/225843.701753:3389166867:INFO:recurring-task.cc(55)] [Retry] Scheduling 40968 with a delay 10000000, Now = 211419424 [4624:4624:0318/225843.701805:3389166915:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b6f0 with delay 10000 [4624:4624:0318/225843.701839:3389166949:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b6b0 [4624:4624:0318/225843.701862:3389166969:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4624:4624:0318/225843.701901:3389167009:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b710 with delay 0 [4624:4624:0318/225843.701927:3389167036:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000b710 [4624:4624:0318/225843.701960:3389167071:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [4624:4624:0318/225843.702010:3389167119:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 167336 with a delay 500000, Now = 211469424 [4624:4624:0318/225843.702035:3389167143:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b730 with delay 500 [4624:4624:0318/225843.702065:3389167175:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 167208 with a delay 60000000, Now = 211469424 [4624:4624:0318/225843.702096:3389167206:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b750 with delay 60000 [4624:4624:0318/225843.702138:3389167246:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000b730 [4624:4624:0318/225843.702160:3389167270:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.702203:3389167321:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.702242:3389167351:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4624:4624:0318/225843.702369:3389167480: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 } } } [4624:4624:0318/225843.702611:3389167725:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000b6f0 [4624:4624:0318/225843.703458:3389168569:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000b310 [4624:4624:0318/225843.703503:3389168611:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x60200000b750 [4624:4624:0318/225843.703545:3389168653: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 [4624:4624:0318/225843.703569:3389168677:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [4624:4624:0318/225843.703636:3389168745: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 } [4624:4624:0318/225843.703668:3389168777:INFO:recurring-task.cc(55)] [Send-info] Scheduling 167336 with a delay 500000, Now = 271469424 [4624:4624:0318/225843.703693:3389168803:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000b7f0 with delay 500 [4624:4624:0318/225843.703735:3389168845:INFO:recurring-task.cc(55)] [Retry] Scheduling 167208 with a delay 60000000, Now = 271469424 [4624:4624:0318/225843.703765:3389168876:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000b810 with delay 60000 [4624:4624:0318/225843.703812:3389168921:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x60200000b7f0 [4624:4624:0318/225843.703842:3389168950:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.703887:3389168998:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.703915:3389169024:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4624:4624:0318/225843.704037:3389169148: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 (6 ms) [26/28] InvalidationClientImplTest.NetworkTimeouts (6 ms) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary [4624:4624:0318/225843.705626:3389170736:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c0f0 with delay 0 [4624:4624:0318/225843.705674:3389170783:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4624:4624:0318/225843.705874:3389170985:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c610 with delay 0 [4624:4624:0318/225843.705907:3389171017:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c0f0 [4624:4624:0318/225843.705940:3389171051:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c610 [4624:4624:0318/225843.705994:3389171104:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4624:4624:0318/225843.706042:3389171150:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c6d0 with delay 0 [4624:4624:0318/225843.706101:3389171210:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c6d0 [4624:4624:0318/225843.706126:3389171235:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4624:4624:0318/225843.706149:3389171258:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c710 with delay 0 [4624:4624:0318/225843.706182:3389171291:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c710 [4624:4624:0318/225843.706203:3389171311:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4624:4624:0318/225843.706229:3389171338:INFO:recurring-task.cc(55)] [Startup] Scheduling 191784 with a delay 0, Now = 210919424 [4624:4624:0318/225843.706279:3389171389:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c730 with delay 0 [4624:4624:0318/225843.706305:3389171413:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c730 [4624:4624:0318/225843.706354:3389171462:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-1701756852001366434" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4624:4624:0318/225843.706383:3389171492:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 192040 with a delay 500000, Now = 210919424 [4624:4624:0318/225843.706412:3389171521:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c750 with delay 500 [4624:4624:0318/225843.706437:3389171545:INFO:recurring-task.cc(55)] [Retry] Scheduling 191784 with a delay 60000000, Now = 210919424 [4624:4624:0318/225843.706460:3389171568:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c770 with delay 60000 [4624:4624:0318/225843.706493:3389171602:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c750 [4624:4624:0318/225843.706516:3389171625:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.706567:3389171678:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.706675:3389171783: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: "-1701756852001366434" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4624:4624:0318/225843.706760:3389171874:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c810 with delay 0 [4624:4624:0318/225843.706801:3389171910:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c810 [4624:4624:0318/225843.706918:3389172028:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-1701756852001366434" 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" } } [4624:4624:0318/225843.706983:3389172092:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-1701756852001366434" [4624:4624:0318/225843.707017:3389172126:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4624:4624:0318/225843.707054:3389172164:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 38264 with a delay 1200000000, Now = 211419424 [4624:4624:0318/225843.707082:3389172190:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c830 with delay 1200000 [4624:4624:0318/225843.707119:3389172229:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4624:4624:0318/225843.707234:3389172343:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4624:4624:0318/225843.707266:3389172376:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 47112 with a delay 0, Now = 211419424 [4624:4624:0318/225843.707294:3389172403:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ca50 with delay 0 [4624:4624:0318/225843.707334:3389172443: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 [4624:4624:0318/225843.707367:3389172476:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ca50 [4624:4624:0318/225843.707449:3389172558:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000cb10 with delay 0 [4624:4624:0318/225843.707491:3389172600:INFO:recurring-task.cc(55)] [Retry] Scheduling 47112 with a delay 10000000, Now = 211419424 [4624:4624:0318/225843.707515:3389172627:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000cb50 with delay 10000 [4624:4624:0318/225843.707541:3389172648:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000cb10 [4624:4624:0318/225843.707562:3389172670:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4624:4624:0318/225843.707607:3389172716:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.707641:3389172752:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000cb70 with delay 0 [4624:4624:0318/225843.707666:3389172775:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000cb70 [4624:4624:0318/225843.707740:3389172850: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" } } [4624:4624:0318/225843.707966:3389173075:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000cb50 [4624:4624:0318/225843.708672:3389173781: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 (3 ms) [27/28] InvalidationClientImplTest.NoRegistrationSummary (3 ms) [ RUN ] InvalidationClientImplTest.Heartbeats [4624:4624:0318/225843.709227:3389174338:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d3d0 with delay 0 [4624:4624:0318/225843.709281:3389174390:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [4624:4624:0318/225843.709469:3389174578:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d8f0 with delay 0 [4624:4624:0318/225843.709505:3389174615:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d3d0 [4624:4624:0318/225843.709534:3389174643:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d8f0 [4624:4624:0318/225843.709578:3389174693:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [4624:4624:0318/225843.709644:3389174754:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d9b0 with delay 0 [4624:4624:0318/225843.709681:3389174791:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d9b0 [4624:4624:0318/225843.709703:3389174811:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [4624:4624:0318/225843.709728:3389174838:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d9f0 with delay 0 [4624:4624:0318/225843.709756:3389174865:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d9f0 [4624:4624:0318/225843.709812:3389174921:INFO:invalidation-client-core.cc(351)] Starting with no previous state [4624:4624:0318/225843.709846:3389174955:INFO:recurring-task.cc(55)] [Startup] Scheduling 210344 with a delay 0, Now = 210919424 [4624:4624:0318/225843.709870:3389174979:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da10 with delay 0 [4624:4624:0318/225843.709896:3389175005:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000da10 [4624:4624:0318/225843.709945:3389175054:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "8770566811092020770" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [4624:4624:0318/225843.709973:3389175082:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 210600 with a delay 500000, Now = 210919424 [4624:4624:0318/225843.710002:3389175110:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da30 with delay 500 [4624:4624:0318/225843.710029:3389175139:INFO:recurring-task.cc(55)] [Retry] Scheduling 210344 with a delay 60000000, Now = 210919424 [4624:4624:0318/225843.710058:3389175169:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da50 with delay 60000 [4624:4624:0318/225843.710091:3389175199:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000da30 [4624:4624:0318/225843.710115:3389175224:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.710150:3389175260:INFO:invalidation-client-core.cc(488)] Return client token = "" [4624:4624:0318/225843.710277:3389175386: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: "8770566811092020770" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [4624:4624:0318/225843.710374:3389175483:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000daf0 with delay 0 [4624:4624:0318/225843.710399:3389175507:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000daf0 [4624:4624:0318/225843.710491:3389175601:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "8770566811092020770" 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" } } [4624:4624:0318/225843.710546:3389175656:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "8770566811092020770" [4624:4624:0318/225843.710583:3389175692:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [4624:4624:0318/225843.710612:3389175721:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 40904 with a delay 1200000000, Now = 211419424 [4624:4624:0318/225843.710639:3389175748:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000db10 with delay 1200000 [4624:4624:0318/225843.710667:3389175778:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [4624:4624:0318/225843.710806:3389175921:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4624:4624:0318/225843.710852:3389175966:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 66888 with a delay 0, Now = 211419424 [4624:4624:0318/225843.710920:3389176036:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000dd30 with delay 0 [4624:4624:0318/225843.710981:3389176096: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 [4624:4624:0318/225843.711030:3389176145:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000dd30 [4624:4624:0318/225843.711115:3389176229:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ddf0 with delay 0 [4624:4624:0318/225843.711162:3389176277:INFO:recurring-task.cc(55)] [Retry] Scheduling 66888 with a delay 10000000, Now = 211419424 [4624:4624:0318/225843.711202:3389176316:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000de30 with delay 10000 [4624:4624:0318/225843.711240:3389176354:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ddf0 [4624:4624:0318/225843.711280:3389176394:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [4624:4624:0318/225843.711529:3389176644:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000de30 [4624:4624:0318/225843.712370:3389177481:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000da50 [4624:4624:0318/225843.730545:3389195661:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x60200000db10 [4624:4624:0318/225843.730650:3389195761:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4624:4624:0318/225843.730702:3389195811:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [4624:4624:0318/225843.730742:3389195850:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [4624:4624:0318/225843.730952:3389196064: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 } [4624:4624:0318/225843.731014:3389196123:INFO:recurring-task.cc(55)] [Send-info] Scheduling 210600 with a delay 500000, Now = 1411419424 [4624:4624:0318/225843.731044:3389196154:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000de50 with delay 500 [4624:4624:0318/225843.731075:3389196185:INFO:recurring-task.cc(55)] [Retry] Scheduling 40904 with a delay 1200000000, Now = 1411419424 [4624:4624:0318/225843.731100:3389196208:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000de70 with delay 1200000 [4624:4624:0318/225843.731136:3389196244:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x60200000de50 [4624:4624:0318/225843.731159:3389196269:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.731218:3389196327:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [4624:4624:0318/225843.731243:3389196352:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [4624:4624:0318/225843.731451:3389196560: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 (24 ms) [28/28] InvalidationClientImplTest.Heartbeats (24 ms) SUCCESS: all tests passed. Tests took 0 seconds. 2019-03-18 23:04:44,149 - root: [DEBUG] Contents of task_output_dir: ['/b/s/w/ir/tmp/t/tmpc6FkML/43ad59468db76510'] 2019-03-18 23:04:44,149 - root: [DEBUG] Found shard_json_files: ['/b/s/w/ir/tmp/t/tmpc6FkML/43ad59468db76510/output.json'] 2019-03-18 23:04:44,149 - root: [INFO] merge_cmd: /b/s/w/ir/cache/vpython/95f307/bin/python /b/s/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --build-properties {"bot_id": "luci-chromium-ci-trusty-32-15-n6go", "branch": "refs/heads/master", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552959643983899, "id": "8918597504309257904", "project": "chromium", "tags": ["build_address:luci.chromium.ci/ToTLinuxASan/5274", "builder:ToTLinuxASan", "buildset:commit/git/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "gitiles_ref:refs/heads/master", "scheduler_invocation_id:9084027566542148080", "scheduler_job_id:chromium/ToTLinuxASan", "user_agent:luci-scheduler"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "ToTLinuxASan", "buildnumber": 5274, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "got_revision_cp": "refs/heads/master@{#641797}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.clang", "path_config": "generic", "perf_dashboard_machine_group": "ChromiumClang", "recipe": "chromium", "repository": "https://chromium.googlesource.com/chromium/src.git", "revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058"} --summary-json /b/s/w/ir/tmp/t/tmpchCwxq.json --task-output-dir /b/s/w/ir/tmp/t/tmpc6FkML -o /b/s/w/ir/tmp/t/tmptMI9MD.json /b/s/w/ir/tmp/t/tmpc6FkML/43ad59468db76510/output.json Running ['/b/s/w/ir/cache/vpython/95f307/bin/python', '/b/s/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "luci-chromium-ci-trusty-32-15-n6go", "branch": "refs/heads/master", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552959643983899, "id": "8918597504309257904", "project": "chromium", "tags": ["build_address:luci.chromium.ci/ToTLinuxASan/5274", "builder:ToTLinuxASan", "buildset:commit/git/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "gitiles_ref:refs/heads/master", "scheduler_invocation_id:9084027566542148080", "scheduler_job_id:chromium/ToTLinuxASan", "user_agent:luci-scheduler"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "ToTLinuxASan", "buildnumber": 5274, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "got_revision_cp": "refs/heads/master@{#641797}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.clang", "path_config": "generic", "perf_dashboard_machine_group": "ChromiumClang", "recipe": "chromium", "repository": "https://chromium.googlesource.com/chromium/src.git", "revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058"}', '--summary-json', '/b/s/w/ir/tmp/t/tmpchCwxq.json', '--task-output-dir', '/b/s/w/ir/tmp/t/tmpc6FkML', '-o', '/b/s/w/ir/tmp/t/tmptMI9MD.json', '/b/s/w/ir/tmp/t/tmpc6FkML/43ad59468db76510/output.json'] in None (env: None) Command ['/b/s/w/ir/cache/vpython/95f307/bin/python', '/b/s/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "luci-chromium-ci-trusty-32-15-n6go", "branch": "refs/heads/master", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552959643983899, "id": "8918597504309257904", "project": "chromium", "tags": ["build_address:luci.chromium.ci/ToTLinuxASan/5274", "builder:ToTLinuxASan", "buildset:commit/git/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/ca4568c9b61cffd89ace1fdba90fc4db1901d058", "gitiles_ref:refs/heads/master", "scheduler_invocation_id:9084027566542148080", "scheduler_job_id:chromium/ToTLinuxASan", "user_agent:luci-scheduler"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "ToTLinuxASan", "buildnumber": 5274, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "fef613365afe5234c1bae9fe33c3d30698d27078", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058", "got_revision_cp": "refs/heads/master@{#641797}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "36585c1b6b1fd69d093706a6c4ad9775506a7885", "got_v8_revision_cp": "refs/heads/7.5.62@{#1}", "got_webrtc_revision": "7dbc0eb2efa4708da5e3e44d2a15bfdee4ceb474", "got_webrtc_revision_cp": "refs/heads/master@{#27160}", "mastername": "chromium.clang", "path_config": "generic", "perf_dashboard_machine_group": "ChromiumClang", "recipe": "chromium", "repository": "https://chromium.googlesource.com/chromium/src.git", "revision": "ca4568c9b61cffd89ace1fdba90fc4db1901d058"}', '--summary-json', '/b/s/w/ir/tmp/t/tmpchCwxq.json', '--task-output-dir', '/b/s/w/ir/tmp/t/tmpc6FkML', '-o', '/b/s/w/ir/tmp/t/tmptMI9MD.json', '/b/s/w/ir/tmp/t/tmpc6FkML/43ad59468db76510/output.json'] returned exit code 0