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

python -u /b/swarming/w/ir/kitchen-checkout/build/scripts/tools/runit.py --show-path --with-third-party-lib -- python /b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/collect_task.py --verbose -o /b/swarming/w/ir/tmp/t/tmp6V3RlW.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpVH3C9N --merge-script /b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --merge-script-stdout-file /b/swarming/w/ir/tmp/t/tmp0O2VnZmerge_script_log --merge-additional-args '[]' --build-properties '{"blamelist": ["chromium-internal-autoroll@skia-corp.google.com.iam.gserviceaccount.com"], "bot_id": "swarm2794-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:5071639625-1lppvbtck1morgivc6sq4dul7klu27sd@developer.gserviceaccount.com", "created_ts": 1555783159564784, "id": "8915636833635380432", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_asan_rel_ng/258848", "builder:linux_chromium_asan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1576210/2", "cq_experimental:false", "user_agent:cq"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_asan_rel_ng", "buildnumber": 258848, "category": "cq", "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "3d7996b3a914b260c21eebcf9e7957344fd1e03f", "got_revision_cp": "refs/heads/master@{#652771}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1576210, "patch_project": "chromium/src", "patch_ref": "refs/changes/10/1576210/2", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 2, "patch_storage": "gerrit", "path_config": "generic", "reason": "CQ", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src", "revision": "HEAD"}' --summary-json-file /b/swarming/w/ir/tmp/t/tmpbMtlgc.json -- swarming collect -server https://chromium-swarm.appspot.com -worker 50 -task-summary-python -task-output-stdout all -verbose -requests-json /b/swarming/w/ir/tmp/t/tmphbDpe9.json in dir /b/swarming/w/ir/k: allow_subannotations: True cmd: ['python', '-u', '/b/swarming/w/ir/kitchen-checkout/build/scripts/tools/runit.py', '--show-path', '--with-third-party-lib', '--', 'python', '/b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/collect_task.py', '--verbose', '-o', '/b/swarming/w/ir/tmp/t/tmp6V3RlW.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpVH3C9N', '--merge-script', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--merge-script-stdout-file', '/b/swarming/w/ir/tmp/t/tmp0O2VnZmerge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"blamelist": ["chromium-internal-autoroll@skia-corp.google.com.iam.gserviceaccount.com"], "bot_id": "swarm2794-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:5071639625-1lppvbtck1morgivc6sq4dul7klu27sd@developer.gserviceaccount.com", "created_ts": 1555783159564784, "id": "8915636833635380432", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_asan_rel_ng/258848", "builder:linux_chromium_asan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1576210/2", "cq_experimental:false", "user_agent:cq"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_asan_rel_ng", "buildnumber": 258848, "category": "cq", "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "3d7996b3a914b260c21eebcf9e7957344fd1e03f", "got_revision_cp": "refs/heads/master@{#652771}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1576210, "patch_project": "chromium/src", "patch_ref": "refs/changes/10/1576210/2", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 2, "patch_storage": "gerrit", "path_config": "generic", "reason": "CQ", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src", "revision": "HEAD"}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmpbMtlgc.json', '--', 'swarming', 'collect', '-server', 'https://chromium-swarm.appspot.com', '-worker', '50', '-task-summary-python', '-task-output-stdout', 'all', '-verbose', '-requests-json', '/b/swarming/w/ir/tmp/t/tmphbDpe9.json'] env: {'CHROME_HEADLESS': '1'} env_prefixes: {'PATH': '/b/swarming/w/ir/cache/swarming_client'} env_suffixes: {} infra_step: False name_tokens: ('cacheinvalidation_unittests (with patch)',) ok_ret: ALL_OK step_test_data: gen_default_step_test_data(...) trigger_specs: () full environment: ADDRFAM: inet BOTO_CONFIG: /b/swarming/w/ir/tmp/gsutil_task/.boto BUILDBUCKET_EXPERIMENTAL: FALSE CHROME_HEADLESS: 1 CIPD_CACHE_DIR: /b/swarming/cipd_cache/cache CIPD_PROTOCOL: v2 DEVSHELL_CLIENT_PORT: 41171 DOCKER_CONFIG: /b/swarming/w/ir/tmp/docker_cfg_task DOCKER_TMPDIR: /b/swarming/w/ir/tmp/docker_tmp_task GIT_CONFIG_NOSYSTEM: 1 GIT_TERMINAL_PROMPT: 0 HOME: /home/chrome-bot IFACE: eth0 INFRA_GIT_WRAPPER_HOME: /b/swarming/w/ir/tmp/git_home_task LOGDOG_COORDINATOR_HOST: logs.chromium.org LOGDOG_STREAM_PREFIX: buildbucket/cr-buildbucket.appspot.com/8915636833635380432 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/itbeW8xp/luci_context.247122270 MAC_CHROMIUM_TMPDIR: /b/swarming/w/ir/tmp/t METHOD: dhcp NO_GCE_CHECK: False PATH: /b/swarming/w/ir/cache/swarming_client:/b/swarming/w/ir/cipd_bin_packages:/b/swarming/w/ir/cipd_bin_packages/bin:/b/swarming/cipd_cache/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin PWD: /b/swarming/w/ir/k PYTHONIOENCODING: UTF-8 PYTHONUNBUFFERED: 1 ROOT_SETUP_LOG: /var/log/messages/chromebuild/root-setup.log SHLVL: 1 STARTUP_LOG: /var/log/messages/chromebuild/startup.log SWARMING_BOT_ID: swarm2794-c4 SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 4454b8b12f47d911 TEMP: /b/swarming/w/ir/tmp/t TEMPDIR: /b/swarming/w/ir/tmp/t TERM: linux TMP: /b/swarming/w/ir/tmp/t TMPDIR: /b/swarming/w/ir/tmp/t UPSTART_EVENTS: net-device-up UPSTART_INSTANCE: UPSTART_JOB: chromebuild-startup USER: chrome-bot USERNAME: chrome-bot VPYTHON_VIRTUALENV_ROOT: /b/swarming/w/ir/cache/vpython _: /b/swarming/w/ir/cipd_bin_packages/vpython Set PYTHONPATH: /b/swarming/w/ir/kitchen-checkout/build/scripts:/b/swarming/w/ir/kitchen-checkout/build/site_config:/b/swarming/w/ir/kitchen-checkout/build/third_party:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_8_4p1:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_slave_8_4:/b/swarming/w/ir/kitchen-checkout/build/third_party/coverage-3.7.1:/b/swarming/w/ir/kitchen-checkout/build/third_party/decorator_3_3_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/google_api_python_client:/b/swarming/w/ir/kitchen-checkout/build/third_party/httplib2/python2:/b/swarming/w/ir/kitchen-checkout/build/third_party/infra_libs:/b/swarming/w/ir/kitchen-checkout/build/third_party/jinja2:/b/swarming/w/ir/kitchen-checkout/build/third_party/markupsafe:/b/swarming/w/ir/kitchen-checkout/build/third_party/oauth2client:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1-modules:/b/swarming/w/ir/kitchen-checkout/build/third_party/python-rsa:/b/swarming/w/ir/kitchen-checkout/build/third_party/requests_2_10_0:/b/swarming/w/ir/kitchen-checkout/build/third_party/setuptools-0.6c11:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_migrate_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/tempita_0_5:/b/swarming/w/ir/kitchen-checkout/build/third_party/twisted_10_2:/b/swarming/w/ir/kitchen-checkout/build/third_party/uritemplate:/b/swarming/w/ir/kitchen-checkout/build/third_party/site-packages 2019-04-20 11:26:42,276 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmpVH3C9N' 2019-04-20 11:26:42,276 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmpVH3C9N' already exists! 2019-04-20 11:26:42,276 - root: [WARNING] task_output_dir existing content: [] 2019-04-20 11:26:42,276 - root: [INFO] collect_cmd: swarming collect -server https://chromium-swarm.appspot.com -worker 50 -task-summary-python -task-output-stdout all -verbose -requests-json /b/swarming/w/ir/tmp/t/tmphbDpe9.json -output-dir /b/swarming/w/ir/tmp/t/tmpVH3C9N -task-summary-json /b/swarming/w/ir/tmp/t/tmpbMtlgc.json [D2019-04-20T11:26:42.284091-07:00 634 0 auth.go:1265] Minting a new token {"key":"luci_ctx/a364f4cd60adc2c9ba91a7622bd997a94604dce334fe6505d81a9866748ab43b", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-04-20T11:26:42.284201-07:00 634 0 luci_ctx.go:138] POST http://127.0.0.1:38339/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/a364f4cd60adc2c9ba91a7622bd997a94604dce334fe6505d81a9866748ab43b", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-04-20T11:26:42.286346-07:00 634 0 auth.go:1222] Token expires in 34m23.713763807s {"key":"luci_ctx/a364f4cd60adc2c9ba91a7622bd997a94604dce334fe6505d81a9866748ab43b", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 4454d066de0cb510: exit 0 /b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:354: SNIMissingWarning: An HTTPS request has been made, but the SNI (Server Name Indication) extension to TLS is not available on this platform. This may cause the server to present an incorrect TLS certificate, which can cause validation failures. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings /b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings /b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings 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/iohJOvc9/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.SendInitializeOnly [27894:27894:0419/113708.291969:23078758008:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cf0 with delay 0 [27894:27894:0419/113708.292470:23078758506:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cf0 [27894:27894:0419/113708.293068:23078759104: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 } [27894:27894:0419/113708.293158:23078759193:INFO:recurring-task.cc(55)] [Startup] Scheduling 24104 with a delay 500000, Now = 210919424 [27894:27894:0419/113708.293247:23078759279:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e90 with delay 500 [27894:27894:0419/113708.293459:23078759498:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001e90 [27894:27894:0419/113708.294025:23078760061: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 (4 ms) [1/28] ProtocolHandlerTest.SendInitializeOnly (4 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [27894:27894:0419/113708.295827:23078761871:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "fake nonce" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } [ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms) [2/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes [27894:27894:0419/113708.296583:23078762618:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002ad0 with delay 0 [27894:27894:0419/113708.296681:23078762712:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002af0 with delay 0 [27894:27894:0419/113708.296768:23078762810:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b10 with delay 0 [27894:27894:0419/113708.296871:23078762907:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b30 with delay 0 [27894:27894:0419/113708.296933:23078762988:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b50 with delay 0 [27894:27894:0419/113708.297023:23078763062:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b70 with delay 0 [27894:27894:0419/113708.297696:23078763744:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002ad0 [27894:27894:0419/113708.297882:23078763918: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 } [27894:27894:0419/113708.297994:23078764042:INFO:recurring-task.cc(55)] [Send-info] Scheduling 35624 with a delay 500000, Now = 210919424 [27894:27894:0419/113708.298073:23078764105:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002d10 with delay 500 [27894:27894:0419/113708.298135:23078764168:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002af0 [27894:27894:0419/113708.298194:23078764230:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b10 [27894:27894:0419/113708.298240:23078764279:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b30 [27894:27894:0419/113708.298293:23078764329:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b50 [27894:27894:0419/113708.298343:23078764377:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b70 [27894:27894:0419/113708.298424:23078764466:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [27894:27894:0419/113708.298625:23078764662:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002d10 [27894:27894:0419/113708.298912:23078764958:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [27894:27894:0419/113708.299540:23078765575: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) [3/28] ProtocolHandlerTest.SendMultipleMessageTypes (4 ms) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage [27894:27894:0419/113708.301860:23078767897: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) [4/28] ProtocolHandlerTest.IncomingCompositeMessage (2 ms) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage [27894:27894:0419/113708.303003:23078769048: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 } } [27894:27894:0419/113708.303194:23078769236: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" } [27894:27894:0419/113708.303358:23078769404: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 } } [27894:27894:0419/113708.303564:23078769602: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) [5/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch [27894:27894:0419/113708.304533:23078770580: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 } } [27894:27894:0419/113708.304744:23078770781: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 (2 ms) [6/28] ProtocolHandlerTest.MajorVersionMismatch (2 ms) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch [27894:27894:0419/113708.305611:23078771651:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 4 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.MinorVersionMismatch (0 ms) [7/28] ProtocolHandlerTest.MinorVersionMismatch (0 ms) [ RUN ] ProtocolHandlerTest.ConfigMessage [27894:27894:0419/113708.306562:23078772602: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" } } [27894:27894:0419/113708.306685:23078772722:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004850 with delay 0 [27894:27894:0419/113708.306746:23078772783:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004850 [27894:27894:0419/113708.306882:23078772921: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 } [27894:27894:0419/113708.306984:23078773022:INFO:recurring-task.cc(55)] [Send-info] Scheduling 66728 with a delay 500000, Now = 210919424 [27894:27894:0419/113708.307052:23078773089:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004870 with delay 500 [27894:27894:0419/113708.307286:23078773328:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004870 [27894:27894:0419/113708.307378:23078773414:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 [ OK ] ProtocolHandlerTest.ConfigMessage (38 ms) [8/28] ProtocolHandlerTest.ConfigMessage (38 ms) [ RUN ] ProtocolHandlerTest.ErrorMessage [27894:27894:0419/113708.344944:23078810981:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.ErrorMessage (1 ms) [9/28] ProtocolHandlerTest.ErrorMessage (1 ms) [ RUN ] ProtocolHandlerTest.TokenMismatch [27894:27894:0419/113708.345556:23078811588:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.TokenMismatch (0 ms) [10/28] ProtocolHandlerTest.TokenMismatch (0 ms) [ RUN ] ProtocolHandlerTest.TokenMissing [27896:27896:0419/113708.305203:23078771250:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cf0 with delay 0 [27896:27896:0419/113708.305369:23078771418:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cf0 [27896:27896:0419/113708.306223:23078772264: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 } [27896:27896:0419/113708.306377:23078772416:INFO:recurring-task.cc(55)] [Send-info] Scheduling 24104 with a delay 500000, Now = 210919424 [27896:27896:0419/113708.306483:23078772527:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001d10 with delay 500 [27896:27896:0419/113708.306729:23078772773:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001d10 [27896:27896:0419/113708.306929:23078772975:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [27896:27896:0419/113708.307022:23078773069:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (3 ms) [11/28] ProtocolHandlerTest.TokenMissing (3 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [27896:27896:0419/113708.308080:23078774131:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002290 with delay 0 [27896:27896:0419/113708.308190:23078774228:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002290 [27896:27896:0419/113708.308323:23078774361:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 29096 with a delay 500000, Now = 210919424 [27896:27896:0419/113708.308418:23078774461:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000022b0 with delay 500 [27896:27896:0419/113708.308650:23078774690:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000022b0 [27896:27896:0419/113708.308968:23078775008:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [27896:27896:0419/113708.309149:23078775195: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 } [27896:27896:0419/113708.309328:23078775366: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 } } [27896:27896:0419/113708.309674:23078775708: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 } } } [27896:27896:0419/113708.309970:23078776024: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 (3 ms) [12/28] ProtocolHandlerTest.InvalidOutboundMessage (3 ms) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage [27896:27896:0419/113708.310975:23078777024:INFO:protocol-handler.cc(139)] Incoming message: { } [27896:27896:0419/113708.311089:23078777129:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [27896:27896:0419/113708.311175:23078777214:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [13/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [ RUN ] RecurringTaskTest.PeriodicTask [27896:27896:0419/113708.311779:23078777824:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 1203949672 with a delay 10000, Now = 0 [27896:27896:0419/113708.311867:23078777903:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002970 with delay 10 [27896:27896:0419/113708.311959:23078778004:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002970 [27896:27896:0419/113708.312043:23078778080:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [27896:27896:0419/113708.312120:23078778156:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203949672 with a delay 60000, Now = 10000 [27896:27896:0419/113708.312210:23078778256:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002990 with delay 60 [27896:27896:0419/113708.312344:23078778385:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x602000002990 [27896:27896:0419/113708.312397:23078778436:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [27896:27896:0419/113708.312472:23078778505:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203949672 with a delay 60000, Now = 70000 [27896:27896:0419/113708.312530:23078778569:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x6020000029b0 with delay 60 [27896:27896:0419/113708.312602:23078778650:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x6020000029b0 [27896:27896:0419/113708.312665:23078778700:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [27896:27896:0419/113708.312718:23078778757:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203949672 with a delay 60000, Now = 130000 [27896:27896:0419/113708.312777:23078778814:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x6020000029d0 with delay 60 [27896:27896:0419/113708.312856:23078778893:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x6020000029d0 [27896:27896:0419/113708.312905:23078778951:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [27896:27896:0419/113708.312981:23078779018:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203949672 with a delay 60000, Now = 190000 [27896:27896:0419/113708.313040:23078779080:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x6020000029f0 with delay 60 [27896:27896:0419/113708.313105:23078779147:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x6020000029f0 [27896:27896:0419/113708.313162:23078779199:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [27896:27896:0419/113708.313224:23078779265:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203949672 with a delay 60000, Now = 250000 [27896:27896:0419/113708.313293:23078779330:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x602000002a10 with delay 60 [27896:27896:0419/113708.313372:23078779416:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x602000002a10 [27896:27896:0419/113708.313422:23078779461:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [27896:27896:0419/113708.313489:23078779524:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203949672 with a delay 60000, Now = 310000 [27896:27896:0419/113708.313545:23078779587:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x602000002a30 with delay 60 [27896:27896:0419/113708.313622:23078779662:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x602000002a30 [27896:27896:0419/113708.313679:23078779714:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [27896:27896:0419/113708.313737:23078779777:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203949672 with a delay 60000, Now = 370000 [27896:27896:0419/113708.313792:23078779834:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x602000002a50 with delay 60 [27896:27896:0419/113708.313863:23078779900:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x602000002a50 [27896:27896:0419/113708.313950:23078779990:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (4 ms) [14/28] RecurringTaskTest.PeriodicTask (4 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [27896:27896:0419/113708.315891:23078781928:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 1203805288 with a delay 10000, Now = 0 [27896:27896:0419/113708.315970:23078782005:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002ad0 with delay 10 [27896:27896:0419/113708.316035:23078782073:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002ad0 [27896:27896:0419/113708.316101:23078782133:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [27896:27896:0419/113708.316158:23078782191:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203805288 with a delay 50000, Now = 10000 [27896:27896:0419/113708.316231:23078782266:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002af0 with delay 50 [27896:27896:0419/113708.316289:23078782320:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x602000002af0 [27896:27896:0419/113708.316354:23078782386:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [27896:27896:0419/113708.316413:23078782447:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203805288 with a delay 149000, Now = 60000 [27896:27896:0419/113708.316478:23078782514:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x602000002b10 with delay 149 [27896:27896:0419/113708.316531:23078782568:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x602000002b10 [27896:27896:0419/113708.316585:23078782622:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [27896:27896:0419/113708.316653:23078782686:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203805288 with a delay 248000, Now = 210000 [27896:27896:0419/113708.316715:23078782751:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x602000002b30 with delay 248 [27896:27896:0419/113708.316771:23078782807:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x602000002b30 [27896:27896:0419/113708.316826:23078782860:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [27896:27896:0419/113708.316876:23078782915:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203805288 with a delay 446000, Now = 460000 [27896:27896:0419/113708.316938:23078782969:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x602000002b50 with delay 446 [27896:27896:0419/113708.317006:23078783044:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x602000002b50 [27896:27896:0419/113708.317045:23078783083:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [27896:27896:0419/113708.317099:23078783133:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203805288 with a delay 842000, Now = 910000 [27896:27896:0419/113708.317153:23078783191:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x602000002b70 with delay 842 [27896:27896:0419/113708.317243:23078783276:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x602000002b70 [27896:27896:0419/113708.317276:23078783307:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [27896:27896:0419/113708.317306:23078783355:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203805288 with a delay 1040000, Now = 1760000 [27896:27896:0419/113708.317357:23078783391:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x602000002b90 with delay 1040 [27896:27896:0419/113708.317439:23078783470:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x602000002b90 [27896:27896:0419/113708.317480:23078783514:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [27896:27896:0419/113708.317522:23078783555:INFO:recurring-task.cc(55)] [Retry] Scheduling 1203805288 with a delay 1040000, Now = 2800000 [27896:27896:0419/113708.317557:23078783588:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x602000002bb0 with delay 1040 [27896:27896:0419/113708.317615:23078783649:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x602000002bb0 [27896:27896:0419/113708.317648:23078783688:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms) [15/28] RecurringTaskTest.ExponentialBackoffTask (3 ms) [ RUN ] RecurringTaskTest.OneShotTask [27896:27896:0419/113708.318718:23078784756:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 1203794024 with a delay 10000, Now = 0 [27896:27896:0419/113708.318792:23078784829:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002c30 with delay 10 [27896:27896:0419/113708.318844:23078784878:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002c30 [27896:27896:0419/113708.318895:23078784931:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [27896:27896:0419/113708.318944:23078784978:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 1203794024 with a delay 10000, Now = 10000 [27896:27896:0419/113708.318995:23078785025:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002c50 with delay 10 [27896:27896:0419/113708.319051:23078785086:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x602000002c50 [27896:27896:0419/113708.319098:23078785139:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (2 ms) [16/28] RecurringTaskTest.OneShotTask (2 ms) [ RUN ] ThrottleTest.ThrottlingScripted [27896:27896:0419/113708.320281:23078786319:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x602000002cd0 with delay 920 [27896:27896:0419/113708.320381:23078786414:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002cd0 [27896:27896:0419/113708.320741:23078786777:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x602000002cf0 with delay 45000 [27896:27896:0419/113708.321603:23078787637:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002cf0 [ OK ] ThrottleTest.ThrottlingScripted (1 ms) [17/28] ThrottleTest.ThrottlingScripted (1 ms) [ RUN ] ThrottleTest.ThrottlingStorm [27896:27896:0419/113708.321823:23078787855:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002d70 with delay 990 [27896:27896:0419/113708.321918:23078787950:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002d70 [27896:27896:0419/113708.322000:23078788035:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x602000002d90 with delay 1000 [27896:27896:0419/113708.322073:23078788104:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x602000002d90 [27896:27896:0419/113708.322114:23078788145:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x602000002db0 with delay 1000 [27896:27896:0419/113708.322176:23078788209:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x602000002db0 [27896:27896:0419/113708.322204:23078788236:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x602000002dd0 with delay 1000 [27896:27896:0419/113708.322267:23078788299:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x602000002dd0 [27896:27896:0419/113708.322299:23078788331:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x602000002df0 with delay 1000 [27896:27896:0419/113708.322383:23078788413:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x602000002df0 [27896:27896:0419/113708.322421:23078788452:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x602000002e10 with delay 1000 [27896:27896:0419/113708.322482:23078788519:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x602000002e10 [27896:27896:0419/113708.322521:23078788556:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x602000002e30 with delay 54000 [27896:27896:0419/113708.324195:23078790231:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002e30 [27896:27896:0419/113708.324243:23078790279:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x602000002e50 with delay 1000 [27896:27896:0419/113708.324325:23078790360:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x602000002e50 [27896:27896:0419/113708.324359:23078790391:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x602000002e70 with delay 1000 [27896:27896:0419/113708.324432:23078790462:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x602000002e70 [27896:27896:0419/113708.324474:23078790507:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x602000002e90 with delay 1000 [27896:27896:0419/113708.324532:23078790567:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x602000002e90 [27896:27896:0419/113708.324568:23078790597:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x602000002eb0 with delay 1000 [27896:27896:0419/113708.324625:23078790660:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x602000002eb0 [27896:27896:0419/113708.324660:23078790692:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x602000002ed0 with delay 1000 [27896:27896:0419/113708.324720:23078790751:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x602000002ed0 [27896:27896:0419/113708.324755:23078790787:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x602000002ef0 with delay 1000 [27896:27896:0419/113708.324829:23078790858:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x602000002ef0 [27896:27896:0419/113708.324858:23078790890:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x602000002f10 with delay 54000 [27896:27896:0419/113708.326550:23078792588:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x602000002f10 [27896:27896:0419/113708.326601:23078792631:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x602000002f30 with delay 1000 [27896:27896:0419/113708.326656:23078792688:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x602000002f30 [27896:27896:0419/113708.326690:23078792723:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x602000002f50 with delay 1000 [27896:27896:0419/113708.326749:23078792780:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x602000002f50 [27896:27896:0419/113708.326773:23078792805:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x602000002f70 with delay 1000 [27896:27896:0419/113708.326832:23078792862:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x602000002f70 [27896:27896:0419/113708.326866:23078792898:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x602000002f90 with delay 1000 [27896:27896:0419/113708.326921:23078792953:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x602000002f90 [27896:27896:0419/113708.326948:23078792980:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x602000002fb0 with delay 1000 [27896:27896:0419/113708.327004:23078793035:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x602000002fb0 [27896:27896:0419/113708.327028:23078793060:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x602000002fd0 with delay 1000 [27896:27896:0419/113708.327092:23078793123:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x602000002fd0 [27896:27896:0419/113708.327114:23078793146:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x602000002ff0 with delay 54000 [27896:27896:0419/113708.328755:23078794785:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x602000002ff0 [27896:27896:0419/113708.328797:23078794830:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x602000003010 with delay 1000 [27896:27896:0419/113708.328855:23078794888:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x602000003010 [27896:27896:0419/113708.328888:23078794917:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x602000003030 with delay 1000 [27896:27896:0419/113708.328951:23078794983:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x602000003030 [27896:27896:0419/113708.328976:23078795008:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x602000003050 with delay 1000 [27896:27896:0419/113708.329031:23078795063:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x602000003050 [27896:27896:0419/113708.329055:23078795088:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x602000003070 with delay 1000 [27896:27896:0419/113708.329117:23078795147:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x602000003070 [27896:27896:0419/113708.329167:23078795202:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x602000003090 with delay 1000 [27896:27896:0419/113708.329231:23078795263:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x602000003090 [27896:27896:0419/113708.329257:23078795287:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x6020000030b0 with delay 1000 [27896:27896:0419/113708.329321:23078795359:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x6020000030b0 [27896:27896:0419/113708.329354:23078795385:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x6020000030d0 with delay 54000 [27896:27896:0419/113708.331014:23078797051:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x6020000030d0 [27896:27896:0419/113708.331055:23078797087:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x6020000030f0 with delay 1000 [27896:27896:0419/113708.331122:23078797152:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x6020000030f0 [27896:27896:0419/113708.331148:23078797181:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x602000003110 with delay 1000 [27896:27896:0419/113708.331202:23078797240:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x602000003110 [27896:27896:0419/113708.331240:23078797269:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x602000003130 with delay 1000 [27896:27896:0419/113708.331293:23078797322:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x602000003130 [27896:27896:0419/113708.331328:23078797360:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x602000003150 with delay 1000 [27896:27896:0419/113708.331382:23078797411:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x602000003150 [27896:27896:0419/113708.331409:23078797439:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x602000003170 with delay 1000 [27896:27896:0419/113708.331461:23078797490:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x602000003170 [27896:27896:0419/113708.331500:23078797530:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x602000003190 with delay 1000 [27896:27896:0419/113708.331552:23078797583:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x602000003190 [27896:27896:0419/113708.331575:23078797605:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x6020000031b0 with delay 54000 [27896:27896:0419/113708.333189:23078799222:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x6020000031b0 [ OK ] ThrottleTest.ThrottlingStorm (12 ms) [18/28] ThrottleTest.ThrottlingStorm (12 ms) [ RUN ] InvalidationClientImplTest.Start [27892:27892:0419/113708.293543:23078759589:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002030 with delay 0 [27892:27892:0419/113708.294447:23078760497:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [27892:27892:0419/113708.295283:23078761329:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002550 with delay 0 [27892:27892:0419/113708.295408:23078761455:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002030 [27892:27892:0419/113708.295503:23078761538:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002550 [27892:27892:0419/113708.295706:23078761758:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [27892:27892:0419/113708.295913:23078761967:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002610 with delay 0 [27892:27892:0419/113708.296046:23078762082:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002610 [27892:27892:0419/113708.296116:23078762154:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [27892:27892:0419/113708.296218:23078762256:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002650 with delay 0 [27892:27892:0419/113708.296306:23078762365:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002650 [27892:27892:0419/113708.296399:23078762449:INFO:invalidation-client-core.cc(351)] Starting with no previous state [27892:27892:0419/113708.296521:23078762553:INFO:recurring-task.cc(55)] [Startup] Scheduling 24360 with a delay 0, Now = 210919424 [27892:27892:0419/113708.296637:23078762686:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002670 with delay 0 [27892:27892:0419/113708.296737:23078762775:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002670 [27892:27892:0419/113708.296913:23078762953:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-2249587174767784525" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [27892:27892:0419/113708.297012:23078763048:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 24616 with a delay 500000, Now = 210919424 [27892:27892:0419/113708.297126:23078763165:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002690 with delay 500 [27892:27892:0419/113708.297206:23078763256:INFO:recurring-task.cc(55)] [Retry] Scheduling 24360 with a delay 60000000, Now = 210919424 [27892:27892:0419/113708.297330:23078763372:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000026b0 with delay 60000 [27892:27892:0419/113708.297569:23078763613:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002690 [27892:27892:0419/113708.297730:23078763769:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.297965:23078764024:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.298346:23078764387: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: "-2249587174767784525" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [27892:27892:0419/113708.298722:23078764759:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002750 with delay 0 [27892:27892:0419/113708.298831:23078764893:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002750 [27892:27892:0419/113708.299202:23078765238:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-2249587174767784525" 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" } } [27892:27892:0419/113708.299364:23078765409:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-2249587174767784525" [27892:27892:0419/113708.299507:23078765550:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [27892:27892:0419/113708.299629:23078765680:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 13448 with a delay 1200000000, Now = 211419424 [27892:27892:0419/113708.299733:23078765775:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002770 with delay 1200000 [27892:27892:0419/113708.299849:23078765911:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [27892:27892:0419/113708.300236:23078766278:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [27892:27892:0419/113708.300342:23078766385:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 9672 with a delay 0, Now = 211419424 [27892:27892:0419/113708.300426:23078766469:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002990 with delay 0 [27892:27892:0419/113708.300575:23078766622: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 [27892:27892:0419/113708.300700:23078766744:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002990 [27892:27892:0419/113708.300925:23078766972:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a50 with delay 0 [27892:27892:0419/113708.301031:23078767064:INFO:recurring-task.cc(55)] [Retry] Scheduling 9672 with a delay 10000000, Now = 211419424 [27892:27892:0419/113708.301095:23078767143:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a90 with delay 10000 [27892:27892:0419/113708.301186:23078767225:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002a50 [27892:27892:0419/113708.301255:23078767296:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (11 ms) [19/28] InvalidationClientImplTest.Start (11 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [27892:27892:0419/113708.302620:23078768656:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000032f0 with delay 0 [27892:27892:0419/113708.302705:23078768741: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 [27892:27892:0419/113708.303477:23078769522:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003b90 with delay 0 [27892:27892:0419/113708.303573:23078769609:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [27892:27892:0419/113708.304050:23078770085:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000041f0 with delay 0 [27892:27892:0419/113708.304130:23078770167:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003b90 [27892:27892:0419/113708.304199:23078770238:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000041f0 [27892:27892:0419/113708.304295:23078770343:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [27892:27892:0419/113708.304411:23078770444:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000042b0 with delay 0 [27892:27892:0419/113708.304481:23078770519:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000042b0 [27892:27892:0419/113708.304540:23078770581:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [27892:27892:0419/113708.304628:23078770666:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000042f0 with delay 0 [27892:27892:0419/113708.304689:23078770723:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000042f0 [27892:27892:0419/113708.304739:23078770771:INFO:invalidation-client-core.cc(351)] Starting with no previous state [27892:27892:0419/113708.304801:23078770838:INFO:recurring-task.cc(55)] [Startup] Scheduling 48296 with a delay 0, Now = 210919424 [27892:27892:0419/113708.304868:23078770908:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004310 with delay 0 [27892:27892:0419/113708.304932:23078770966:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004310 [27892:27892:0419/113708.305032:23078771068:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-653040621755265034" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [27892:27892:0419/113708.305099:23078771134:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 48552 with a delay 500000, Now = 210919424 [27892:27892:0419/113708.305161:23078771198:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004330 with delay 500 [27892:27892:0419/113708.305207:23078771242:INFO:recurring-task.cc(55)] [Retry] Scheduling 48296 with a delay 60000000, Now = 210919424 [27892:27892:0419/113708.305249:23078771295:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004350 with delay 60000 [27892:27892:0419/113708.305437:23078771468:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004330 [27892:27892:0419/113708.305490:23078771539:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.305596:23078771634:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.305850:23078771898: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: "-653040621755265034" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [27892:27892:0419/113708.306058:23078772094:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000043f0 with delay 0 [27892:27892:0419/113708.306125:23078772162:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000043f0 [27892:27892:0419/113708.306306:23078772353:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-653040621755265034" 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" } } [27892:27892:0419/113708.306419:23078772455:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-653040621755265034" [27892:27892:0419/113708.306477:23078772510:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [27892:27892:0419/113708.306545:23078772583:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 15736 with a delay 1200000000, Now = 211419424 [27892:27892:0419/113708.306595:23078772635:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004410 with delay 1200000 [27892:27892:0419/113708.306662:23078772701:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [27892:27892:0419/113708.306927:23078772961:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [27892:27892:0419/113708.307001:23078773036:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 14088 with a delay 0, Now = 211419424 [27892:27892:0419/113708.307054:23078773089:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004630 with delay 0 [27892:27892:0419/113708.307138:23078773173: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 [27892:27892:0419/113708.307221:23078773256:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004630 [27892:27892:0419/113708.307370:23078773402:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000046f0 with delay 0 [27892:27892:0419/113708.307443:23078773478:INFO:recurring-task.cc(55)] [Retry] Scheduling 14088 with a delay 10000000, Now = 211419424 [27892:27892:0419/113708.307490:23078773533:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004730 with delay 10000 [27892:27892:0419/113708.307563:23078773593:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000046f0 [27892:27892:0419/113708.307608:23078773646:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [27892:27892:0419/113708.307728:23078773767:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004750 with delay 0 [27892:27892:0419/113708.307799:23078773833:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000004750 [27892:27892:0419/113708.307883:23078773916:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [27892:27892:0419/113708.307956:23078773992:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [27892:27892:0419/113708.308004:23078774034:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [27892:27892:0419/113708.308114:23078774148:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 48552 with a delay 500000, Now = 211469424 [27892:27892:0419/113708.308165:23078774199:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004770 with delay 500 [27892:27892:0419/113708.308220:23078774253:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 48424 with a delay 60000000, Now = 211469424 [27892:27892:0419/113708.308266:23078774302:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004790 with delay 60000 [27892:27892:0419/113708.308462:23078774499:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000004770 [27892:27892:0419/113708.308523:23078774562:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.308601:23078774636:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.308676:23078774711:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [27892:27892:0419/113708.308899:23078774931: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 } } } [27892:27892:0419/113708.309041:23078775075:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.309157:23078775189:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000004830 with delay 0 [27892:27892:0419/113708.309199:23078775233:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000004830 [27892:27892:0419/113708.309511:23078775543: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 } } } } [27892:27892:0419/113708.309636:23078775668: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 [27892:27892:0419/113708.309738:23078775771:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [27892:27892:0419/113708.309878:23078775909:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [27892:27892:0419/113708.310003:23078776039:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [27892:27892:0419/113708.310537:23078776575:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000004730 [ OK ] InvalidationClientImplTest.Register (8 ms) [21/28] InvalidationClientImplTest.Register (8 ms) [ RUN ] InvalidationClientImplTest.Invalidations [27892:27892:0419/113708.312422:23078778458:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005410 with delay 0 [27892:27892:0419/113708.312501:23078778535:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [27892:27892:0419/113708.312964:23078778998:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005af0 with delay 0 [27892:27892:0419/113708.313010:23078779044:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005410 [27892:27892:0419/113708.313060:23078779094:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005af0 [27892:27892:0419/113708.313142:23078779176:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [27892:27892:0419/113708.313230:23078779263:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005bb0 with delay 0 [27892:27892:0419/113708.313279:23078779312:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005bb0 [27892:27892:0419/113708.313324:23078779355:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [27892:27892:0419/113708.313382:23078779415:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005bf0 with delay 0 [27892:27892:0419/113708.313426:23078779460:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005bf0 [27892:27892:0419/113708.313461:23078779492:INFO:invalidation-client-core.cc(351)] Starting with no previous state [27892:27892:0419/113708.313510:23078779543:INFO:recurring-task.cc(55)] [Startup] Scheduling 79400 with a delay 0, Now = 210919424 [27892:27892:0419/113708.313563:23078779596:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c10 with delay 0 [27892:27892:0419/113708.313610:23078779643:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005c10 [27892:27892:0419/113708.313699:23078779732:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-8762733942682798674" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [27892:27892:0419/113708.313756:23078779791:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 79656 with a delay 500000, Now = 210919424 [27892:27892:0419/113708.313796:23078779827:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c30 with delay 500 [27892:27892:0419/113708.313837:23078779870:INFO:recurring-task.cc(55)] [Retry] Scheduling 79400 with a delay 60000000, Now = 210919424 [27892:27892:0419/113708.313879:23078779919:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c50 with delay 60000 [27892:27892:0419/113708.313938:23078779969:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005c30 [27892:27892:0419/113708.313975:23078780034:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.314058:23078780093:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.314208:23078780239: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: "-8762733942682798674" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [27892:27892:0419/113708.314379:23078780413:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005cf0 with delay 0 [27892:27892:0419/113708.314428:23078780466:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005cf0 [27892:27892:0419/113708.314583:23078780617:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-8762733942682798674" 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" } } [27892:27892:0419/113708.314661:23078780697:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-8762733942682798674" [27892:27892:0419/113708.314705:23078780744:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [27892:27892:0419/113708.314751:23078780784:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 20840 with a delay 1200000000, Now = 211419424 [27892:27892:0419/113708.314802:23078780833:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005d10 with delay 1200000 [27892:27892:0419/113708.314841:23078780874:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [27892:27892:0419/113708.315019:23078781051:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [27892:27892:0419/113708.315071:23078781103:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 20808 with a delay 0, Now = 211419424 [27892:27892:0419/113708.315109:23078781141:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005f30 with delay 0 [27892:27892:0419/113708.315165:23078781199: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 [27892:27892:0419/113708.315245:23078781277:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005f30 [27892:27892:0419/113708.315339:23078781370:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005ff0 with delay 0 [27892:27892:0419/113708.315402:23078781438:INFO:recurring-task.cc(55)] [Retry] Scheduling 20808 with a delay 10000000, Now = 211419424 [27892:27892:0419/113708.315447:23078781479:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000006030 with delay 10000 [27892:27892:0419/113708.315477:23078781507:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005ff0 [27892:27892:0419/113708.315508:23078781540:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [27892:27892:0419/113708.315581:23078781617:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.315659:23078781691:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000006050 with delay 0 [27892:27892:0419/113708.315695:23078781727:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000006050 [27892:27892:0419/113708.315939:23078781972: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 } } } [27892:27892:0419/113708.316036:23078782069: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 [27892:27892:0419/113708.316140:23078782172: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" } [27892:27892:0419/113708.316258:23078782289:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [27892:27892:0419/113708.316348:23078782381:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [27892:27892:0419/113708.316461:23078782498:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006430 with delay 0 [27892:27892:0419/113708.316507:23078782539:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006450 with delay 0 [27892:27892:0419/113708.316548:23078782579:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006470 with delay 0 [27892:27892:0419/113708.316577:23078782608:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006430 [27892:27892:0419/113708.316644:23078782676:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 79656 with a delay 500000, Now = 211519424 [27892:27892:0419/113708.316696:23078782727:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006490 with delay 500 [27892:27892:0419/113708.316740:23078782771:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006450 [27892:27892:0419/113708.316777:23078782808:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006470 [27892:27892:0419/113708.316834:23078782866:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x602000006490 [27892:27892:0419/113708.316876:23078782907:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.316964:23078782995:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.317001:23078783033:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [27892:27892:0419/113708.317196:23078783230:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777601100 max_known_server_time_ms: 314159265 message_id: "2" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } } } [ OK ] InvalidationClientImplTest.Invalidations (5 ms) [22/28] InvalidationClientImplTest.Invalidations (5 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [27892:27892:0419/113708.318166:23078784199:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006d70 with delay 0 [27892:27892:0419/113708.318237:23078784268:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [27892:27892:0419/113708.318515:23078784549:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007290 with delay 0 [27892:27892:0419/113708.318557:23078784589:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006d70 [27892:27892:0419/113708.318588:23078784619:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007290 [27892:27892:0419/113708.318655:23078784688:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [27892:27892:0419/113708.318719:23078784752:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007350 with delay 0 [27892:27892:0419/113708.318767:23078784800:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007350 [27892:27892:0419/113708.318797:23078784828:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [27892:27892:0419/113708.318832:23078784864:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007390 with delay 0 [27892:27892:0419/113708.318878:23078784909:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007390 [27892:27892:0419/113708.318909:23078784942:INFO:invalidation-client-core.cc(351)] Starting with no previous state [27892:27892:0419/113708.318954:23078784986:INFO:recurring-task.cc(55)] [Startup] Scheduling 109096 with a delay 0, Now = 210919424 [27892:27892:0419/113708.319000:23078785033:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073b0 with delay 0 [27892:27892:0419/113708.319031:23078785062:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000073b0 [27892:27892:0419/113708.319105:23078785137:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-5515699452244483394" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [27892:27892:0419/113708.319150:23078785183:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 109352 with a delay 500000, Now = 210919424 [27892:27892:0419/113708.319185:23078785218:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073d0 with delay 500 [27892:27892:0419/113708.319229:23078785260:INFO:recurring-task.cc(55)] [Retry] Scheduling 109096 with a delay 60000000, Now = 210919424 [27892:27892:0419/113708.319266:23078785298:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073f0 with delay 60000 [27892:27892:0419/113708.319352:23078785387:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000073d0 [27892:27892:0419/113708.319399:23078785431:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.319453:23078785486:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.319580:23078785612: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: "-5515699452244483394" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [27892:27892:0419/113708.319709:23078785742:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007490 with delay 0 [27892:27892:0419/113708.319753:23078785785:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007490 [27892:27892:0419/113708.319879:23078785911:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-5515699452244483394" 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" } } [27892:27892:0419/113708.319946:23078785978:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-5515699452244483394" [27892:27892:0419/113708.319992:23078786023:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [27892:27892:0419/113708.320037:23078786071:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 24888 with a delay 1200000000, Now = 211419424 [27892:27892:0419/113708.320073:23078786105:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000074b0 with delay 1200000 [27892:27892:0419/113708.320114:23078786145:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [27892:27892:0419/113708.320273:23078786306:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [27892:27892:0419/113708.320328:23078786360:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 26952 with a delay 0, Now = 211419424 [27892:27892:0419/113708.320365:23078786395:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000076d0 with delay 0 [27892:27892:0419/113708.320428:23078786461: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 [27892:27892:0419/113708.320479:23078786511:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000076d0 [27892:27892:0419/113708.320568:23078786603:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007790 with delay 0 [27892:27892:0419/113708.320613:23078786645:INFO:recurring-task.cc(55)] [Retry] Scheduling 26952 with a delay 10000000, Now = 211419424 [27892:27892:0419/113708.320650:23078786682:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000077d0 with delay 10000 [27892:27892:0419/113708.320685:23078786717:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007790 [27892:27892:0419/113708.320712:23078786744:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [27892:27892:0419/113708.320777:23078786809:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.320827:23078786859:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000077f0 with delay 0 [27892:27892:0419/113708.320875:23078786907:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x6020000077f0 [27892:27892:0419/113708.321010:23078787041: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 } } [27892:27892:0419/113708.321092:23078787123: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 [27892:27892:0419/113708.321136:23078787167:INFO:protocol-handler.cc(294)] Adding subtree: { } [27892:27892:0419/113708.321172:23078787205:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 109352 with a delay 500000, Now = 211469424 [27892:27892:0419/113708.321214:23078787245:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000007810 with delay 500 [27892:27892:0419/113708.321245:23078787279:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [27892:27892:0419/113708.321475:23078787507: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 } [27892:27892:0419/113708.321587:23078787624:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000007810 [27892:27892:0419/113708.321643:23078787676:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.321717:23078787749:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.321755:23078787789:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [27892:27892:0419/113708.322188:23078788222: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 } } [27892:27892:0419/113708.322719:23078788753:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x6020000077d0 [ OK ] InvalidationClientImplTest.ServerRequests (6 ms) [23/28] InvalidationClientImplTest.ServerRequests (6 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [27892:27892:0419/113708.324415:23078790449:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000080f0 with delay 0 [27892:27892:0419/113708.324476:23078790507:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [27892:27892:0419/113708.324750:23078790782:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000086b0 with delay 0 [27892:27892:0419/113708.324785:23078790816:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000080f0 [27892:27892:0419/113708.324815:23078790847:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000086b0 [27892:27892:0419/113708.324882:23078790914:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [27892:27892:0419/113708.324954:23078790986:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008770 with delay 0 [27892:27892:0419/113708.325013:23078791046:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008770 [27892:27892:0419/113708.325040:23078791070:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [27892:27892:0419/113708.325076:23078791108:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087b0 with delay 0 [27892:27892:0419/113708.325109:23078791140:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087b0 [27892:27892:0419/113708.325133:23078791165:INFO:invalidation-client-core.cc(351)] Starting with no previous state [27892:27892:0419/113708.325167:23078791202:INFO:recurring-task.cc(55)] [Startup] Scheduling 136360 with a delay 0, Now = 210919424 [27892:27892:0419/113708.325204:23078791235:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087d0 with delay 0 [27892:27892:0419/113708.325244:23078791276:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087d0 [27892:27892:0419/113708.325306:23078791349:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "3751069093458452183" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [27892:27892:0419/113708.325356:23078791389:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 136616 with a delay 500000, Now = 210919424 [27892:27892:0419/113708.325401:23078791433:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087f0 with delay 500 [27892:27892:0419/113708.325435:23078791471:INFO:recurring-task.cc(55)] [Retry] Scheduling 136360 with a delay 60000000, Now = 210919424 [27892:27892:0419/113708.325481:23078791515:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008810 with delay 60000 [27892:27892:0419/113708.325549:23078791586:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000087f0 [27892:27892:0419/113708.325593:23078791633:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.325666:23078791698:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.325826:23078791857: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: "3751069093458452183" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [27892:27892:0419/113708.325960:23078791992:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000088b0 with delay 0 [27892:27892:0419/113708.326021:23078792052:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000088b0 [27892:27892:0419/113708.326148:23078792180:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "3751069093458452183" 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" } } [27892:27892:0419/113708.326214:23078792245:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "3751069093458452183" [27892:27892:0419/113708.326257:23078792293:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [27892:27892:0419/113708.326297:23078792330:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 28408 with a delay 1200000000, Now = 211419424 [27892:27892:0419/113708.326343:23078792376:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000088d0 with delay 1200000 [27892:27892:0419/113708.326391:23078792423:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [27892:27892:0419/113708.326541:23078792573:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [27892:27892:0419/113708.326574:23078792605:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 32328 with a delay 0, Now = 211419424 [27892:27892:0419/113708.326605:23078792637:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008af0 with delay 0 [27892:27892:0419/113708.326652:23078792683: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 [27892:27892:0419/113708.326691:23078792722:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008af0 [27892:27892:0419/113708.326782:23078792814:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008bb0 with delay 0 [27892:27892:0419/113708.326823:23078792855:INFO:recurring-task.cc(55)] [Retry] Scheduling 32328 with a delay 10000000, Now = 211419424 [27892:27892:0419/113708.326871:23078792902:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008bf0 with delay 10000 [27892:27892:0419/113708.326902:23078792934:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008bb0 [27892:27892:0419/113708.326929:23078792961:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [27892:27892:0419/113708.326991:23078793021:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.327046:23078793078:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000008c10 with delay 0 [27892:27892:0419/113708.327088:23078793121:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000008c10 [27892:27892:0419/113708.327195:23078793227: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" } } [27892:27892:0419/113708.327280:23078793311: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 [27892:27892:0419/113708.327329:23078793361:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [27892:27892:0419/113708.327732:23078793764:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000008bf0 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [24/28] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [27892:27892:0419/113708.329274:23078795308:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009570 with delay 0 [27892:27892:0419/113708.329361:23078795393:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [27892:27892:0419/113708.329662:23078795694:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009bf0 with delay 0 [27892:27892:0419/113708.329698:23078795730:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009570 [27892:27892:0419/113708.329735:23078795766:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009bf0 [27892:27892:0419/113708.329790:23078795821:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [27892:27892:0419/113708.329852:23078795892:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009cb0 with delay 0 [27892:27892:0419/113708.329907:23078795938:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009cb0 [27892:27892:0419/113708.329944:23078795976:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [27892:27892:0419/113708.330006:23078796043:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009cf0 with delay 0 [27892:27892:0419/113708.330059:23078796090:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009cf0 [27892:27892:0419/113708.330086:23078796118:INFO:invalidation-client-core.cc(351)] Starting with no previous state [27892:27892:0419/113708.330128:23078796160:INFO:recurring-task.cc(55)] [Startup] Scheduling 159016 with a delay 0, Now = 210919424 [27892:27892:0419/113708.330161:23078796191:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d10 with delay 0 [27892:27892:0419/113708.330191:23078796223:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009d10 [27892:27892:0419/113708.330284:23078796316:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-3779895791315435436" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [27892:27892:0419/113708.330333:23078796370:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 159272 with a delay 500000, Now = 210919424 [27892:27892:0419/113708.330388:23078796425:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d30 with delay 500 [27892:27892:0419/113708.330427:23078796459:INFO:recurring-task.cc(55)] [Retry] Scheduling 159016 with a delay 60000000, Now = 210919424 [27892:27892:0419/113708.330457:23078796489:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d50 with delay 60000 [27892:27892:0419/113708.330503:23078796534:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009d30 [27892:27892:0419/113708.330531:23078796563:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.330580:23078796611:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.330742:23078796774: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: "-3779895791315435436" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [27892:27892:0419/113708.330899:23078796930:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009df0 with delay 0 [27892:27892:0419/113708.330933:23078796965:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009df0 [27892:27892:0419/113708.331082:23078797114:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-3779895791315435436" 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" } } [27892:27892:0419/113708.331147:23078797178:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-3779895791315435436" [27892:27892:0419/113708.331183:23078797216:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [27892:27892:0419/113708.331221:23078797253:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 31576 with a delay 1200000000, Now = 211419424 [27892:27892:0419/113708.331255:23078797287:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009e10 with delay 1200000 [27892:27892:0419/113708.331290:23078797321:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [27892:27892:0419/113708.331479:23078797516:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [27892:27892:0419/113708.331531:23078797563:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 35976 with a delay 0, Now = 211419424 [27892:27892:0419/113708.331565:23078797597:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a030 with delay 0 [27892:27892:0419/113708.331624:23078797656: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 [27892:27892:0419/113708.331664:23078797696:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a030 [27892:27892:0419/113708.331741:23078797773:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a0f0 with delay 0 [27892:27892:0419/113708.331781:23078797813:INFO:recurring-task.cc(55)] [Retry] Scheduling 35976 with a delay 10000000, Now = 211419424 [27892:27892:0419/113708.331811:23078797847:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a130 with delay 10000 [27892:27892:0419/113708.331847:23078797887:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a0f0 [27892:27892:0419/113708.331881:23078797913:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [27892:27892:0419/113708.331946:23078797978:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a150 with delay 0 [27892:27892:0419/113708.331974:23078798006:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000a150 [27892:27892:0419/113708.332018:23078798050:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [27892:27892:0419/113708.332080:23078798111:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 159272 with a delay 500000, Now = 211469424 [27892:27892:0419/113708.332121:23078798153:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a170 with delay 500 [27892:27892:0419/113708.332157:23078798188:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 159144 with a delay 60000000, Now = 211469424 [27892:27892:0419/113708.332189:23078798221:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a190 with delay 60000 [27892:27892:0419/113708.332248:23078798279:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000a170 [27892:27892:0419/113708.332283:23078798314:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.332339:23078798370:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.332371:23078798403:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [27892:27892:0419/113708.332512:23078798545: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 } } } [27892:27892:0419/113708.332610:23078798642:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.332670:23078798707:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x60200000a230 with delay 0 [27892:27892:0419/113708.332716:23078798752:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000a230 [27892:27892:0419/113708.332832:23078798863: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" } } [27892:27892:0419/113708.332922:23078798953: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 [27892:27892:0419/113708.332955:23078798995:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [27892:27892:0419/113708.333059:23078799090:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [27892:27892:0419/113708.333444:23078799477:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000a130 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms) [25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [27892:27892:0419/113708.335013:23078801048:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ac90 with delay 0 [27892:27892:0419/113708.335079:23078801111:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [27892:27892:0419/113708.335337:23078801369:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b1b0 with delay 0 [27892:27892:0419/113708.335377:23078801409:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000ac90 [27892:27892:0419/113708.335413:23078801444:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b1b0 [27892:27892:0419/113708.335467:23078801498:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [27892:27892:0419/113708.335529:23078801568:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b270 with delay 0 [27892:27892:0419/113708.335582:23078801619:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b270 [27892:27892:0419/113708.335632:23078801667:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [27892:27892:0419/113708.335674:23078801706:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2b0 with delay 0 [27892:27892:0419/113708.335715:23078801746:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b2b0 [27892:27892:0419/113708.335740:23078801771:INFO:invalidation-client-core.cc(351)] Starting with no previous state [27892:27892:0419/113708.335775:23078801806:INFO:recurring-task.cc(55)] [Startup] Scheduling 187432 with a delay 0, Now = 210919424 [27892:27892:0419/113708.335810:23078801841:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2d0 with delay 0 [27892:27892:0419/113708.335842:23078801873:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b2d0 [27892:27892:0419/113708.335914:23078801945:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "5753992072347513155" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [27892:27892:0419/113708.335947:23078801978:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 187688 with a delay 500000, Now = 210919424 [27892:27892:0419/113708.335979:23078802010:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2f0 with delay 500 [27892:27892:0419/113708.336012:23078802043:INFO:recurring-task.cc(55)] [Retry] Scheduling 187432 with a delay 60000000, Now = 210919424 [27892:27892:0419/113708.336044:23078802075:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b310 with delay 60000 [27892:27892:0419/113708.336096:23078802128:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b2f0 [27892:27892:0419/113708.336126:23078802158:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.336173:23078802204:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.336306:23078802351: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: "5753992072347513155" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [27892:27892:0419/113708.336461:23078802492:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b3b0 with delay 0 [27892:27892:0419/113708.336493:23078802525:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b3b0 [27892:27892:0419/113708.336598:23078802629:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "5753992072347513155" 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" } } [27892:27892:0419/113708.336654:23078802684:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "5753992072347513155" [27892:27892:0419/113708.336687:23078802719:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [27892:27892:0419/113708.336724:23078802755:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 34920 with a delay 1200000000, Now = 211419424 [27892:27892:0419/113708.336762:23078802793:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b3d0 with delay 1200000 [27892:27892:0419/113708.336800:23078802831:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [27892:27892:0419/113708.336957:23078802989:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [27892:27892:0419/113708.336999:23078803032:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 41352 with a delay 0, Now = 211419424 [27892:27892:0419/113708.337036:23078803068:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b5f0 with delay 0 [27892:27892:0419/113708.337086:23078803117: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 [27892:27892:0419/113708.337124:23078803155:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b5f0 [27892:27892:0419/113708.337196:23078803228:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b6b0 with delay 0 [27892:27892:0419/113708.337236:23078803267:INFO:recurring-task.cc(55)] [Retry] Scheduling 41352 with a delay 10000000, Now = 211419424 [27892:27892:0419/113708.337266:23078803299:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b6f0 with delay 10000 [27892:27892:0419/113708.337298:23078803330:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b6b0 [27892:27892:0419/113708.337342:23078803374:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [27892:27892:0419/113708.337400:23078803431:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b710 with delay 0 [27892:27892:0419/113708.337431:23078803463:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000b710 [27892:27892:0419/113708.337474:23078803506:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [27892:27892:0419/113708.337538:23078803571:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 187688 with a delay 500000, Now = 211469424 [27892:27892:0419/113708.337585:23078803617:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b730 with delay 500 [27892:27892:0419/113708.337617:23078803649:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 187560 with a delay 60000000, Now = 211469424 [27892:27892:0419/113708.337649:23078803687:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b750 with delay 60000 [27892:27892:0419/113708.337719:23078803751:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000b730 [27892:27892:0419/113708.337751:23078803783:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.337794:23078803825:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.337825:23078803857:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [27892:27892:0419/113708.337961:23078803993: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 } } } [27892:27892:0419/113708.338341:23078804373:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000b6f0 [27892:27892:0419/113708.339372:23078805405:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000b310 [27892:27892:0419/113708.339416:23078805446:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x60200000b750 [27892:27892:0419/113708.339489:23078805521: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 [27892:27892:0419/113708.339531:23078805562:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [27892:27892:0419/113708.339603:23078805637: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 } [27892:27892:0419/113708.339644:23078805675:INFO:recurring-task.cc(55)] [Send-info] Scheduling 187688 with a delay 500000, Now = 271469424 [27892:27892:0419/113708.339681:23078805712:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000b7f0 with delay 500 [27892:27892:0419/113708.339709:23078805742:INFO:recurring-task.cc(55)] [Retry] Scheduling 187560 with a delay 60000000, Now = 271469424 [27892:27892:0419/113708.339749:23078805781:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000b810 with delay 60000 [27892:27892:0419/113708.339794:23078805825:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x60200000b7f0 [27892:27892:0419/113708.339822:23078805853:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.339883:23078805914:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.339912:23078805946:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [27892:27892:0419/113708.340065:23078806101:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 1 registration_digest: "\327\003\047\242\324@\3740-O\354\3229\352\000\231\340\204\224\323" } client_time_ms: 777661050 max_known_server_time_ms: 314159265 message_id: "3" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "InvClientTest" } server_registration_summary_requested: true } } [ OK ] InvalidationClientImplTest.NetworkTimeouts (7 ms) [26/28] InvalidationClientImplTest.NetworkTimeouts (7 ms) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary [27892:27892:0419/113708.341931:23078807965:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c0f0 with delay 0 [27892:27892:0419/113708.342009:23078808040:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [27892:27892:0419/113708.342253:23078808286:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c610 with delay 0 [27892:27892:0419/113708.342289:23078808321:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c0f0 [27892:27892:0419/113708.342331:23078808363:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c610 [27892:27892:0419/113708.342388:23078808420:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [27892:27892:0419/113708.342448:23078808479:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c6d0 with delay 0 [27892:27892:0419/113708.342485:23078808516:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c6d0 [27892:27892:0419/113708.342509:23078808540:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [27892:27892:0419/113708.342548:23078808579:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c710 with delay 0 [27892:27892:0419/113708.342576:23078808608:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c710 [27892:27892:0419/113708.342602:23078808634:INFO:invalidation-client-core.cc(351)] Starting with no previous state [27892:27892:0419/113708.342642:23078808674:INFO:recurring-task.cc(55)] [Startup] Scheduling 216360 with a delay 0, Now = 210919424 [27892:27892:0419/113708.342674:23078808706:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c730 with delay 0 [27892:27892:0419/113708.342708:23078808739:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c730 [27892:27892:0419/113708.342779:23078808811:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-717130329530685717" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [27892:27892:0419/113708.342816:23078808848:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 216616 with a delay 500000, Now = 210919424 [27892:27892:0419/113708.342848:23078808886:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c750 with delay 500 [27892:27892:0419/113708.342909:23078808941:INFO:recurring-task.cc(55)] [Retry] Scheduling 216360 with a delay 60000000, Now = 210919424 [27892:27892:0419/113708.342943:23078808974:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c770 with delay 60000 [27892:27892:0419/113708.342984:23078809015:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c750 [27892:27892:0419/113708.343014:23078809046:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.343061:23078809093:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.343183:23078809215: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: "-717130329530685717" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [27892:27892:0419/113708.343307:23078809351:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c810 with delay 0 [27892:27892:0419/113708.343356:23078809390:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c810 [27892:27892:0419/113708.343500:23078809532:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-717130329530685717" 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" } } [27892:27892:0419/113708.343552:23078809584:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-717130329530685717" [27892:27892:0419/113708.343589:23078809619:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [27892:27892:0419/113708.343626:23078809658:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 37560 with a delay 1200000000, Now = 211419424 [27892:27892:0419/113708.343656:23078809689:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c830 with delay 1200000 [27892:27892:0419/113708.343693:23078809724:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [27892:27892:0419/113708.343840:23078809873:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [27892:27892:0419/113708.343887:23078809919:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 47304 with a delay 0, Now = 211419424 [27892:27892:0419/113708.343920:23078809951:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ca50 with delay 0 [27892:27892:0419/113708.343969:23078810000: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 [27892:27892:0419/113708.344020:23078810052:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ca50 [27892:27892:0419/113708.344088:23078810120:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000cb10 with delay 0 [27892:27892:0419/113708.344131:23078810165:INFO:recurring-task.cc(55)] [Retry] Scheduling 47304 with a delay 10000000, Now = 211419424 [27892:27892:0419/113708.344162:23078810193:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000cb50 with delay 10000 [27892:27892:0419/113708.344198:23078810229:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000cb10 [27892:27892:0419/113708.344222:23078810253:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [27892:27892:0419/113708.344273:23078810305:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.344325:23078810356:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000cb70 with delay 0 [27892:27892:0419/113708.344357:23078810391:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000cb70 [27892:27892:0419/113708.344444:23078810475: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" } } [27892:27892:0419/113708.344740:23078810772:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000cb50 [27892:27892:0419/113708.345655:23078811689:INFO:invalidation-client-impl_test.cc(477)] Reg manager state: { client_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_summary: { num_registrations: 1 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } } [ OK ] InvalidationClientImplTest.NoRegistrationSummary (4 ms) [27/28] InvalidationClientImplTest.NoRegistrationSummary (4 ms) [ RUN ] InvalidationClientImplTest.Heartbeats [27892:27892:0419/113708.346352:23078812391:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d3d0 with delay 0 [27892:27892:0419/113708.346444:23078812480:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [27892:27892:0419/113708.346681:23078812713:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d8f0 with delay 0 [27892:27892:0419/113708.346744:23078812776:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d3d0 [27892:27892:0419/113708.346774:23078812806:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d8f0 [27892:27892:0419/113708.346832:23078812864:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [27892:27892:0419/113708.348158:23078814192:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d9b0 with delay 0 [27892:27892:0419/113708.348200:23078814232:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d9b0 [27892:27892:0419/113708.348228:23078814258:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [27892:27892:0419/113708.348260:23078814292:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d9f0 with delay 0 [27892:27892:0419/113708.348293:23078814323:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d9f0 [27892:27892:0419/113708.348325:23078814355:INFO:invalidation-client-core.cc(351)] Starting with no previous state [27892:27892:0419/113708.348358:23078814391:INFO:recurring-task.cc(55)] [Startup] Scheduling 237992 with a delay 0, Now = 210919424 [27892:27892:0419/113708.348396:23078814427:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da10 with delay 0 [27892:27892:0419/113708.348426:23078814456:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000da10 [27892:27892:0419/113708.348484:23078814515:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-669528170259921202" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [27892:27892:0419/113708.348518:23078814549:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 238248 with a delay 500000, Now = 210919424 [27892:27892:0419/113708.348560:23078814590:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da30 with delay 500 [27892:27892:0419/113708.348588:23078814619:INFO:recurring-task.cc(55)] [Retry] Scheduling 237992 with a delay 60000000, Now = 210919424 [27892:27892:0419/113708.348615:23078814647:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da50 with delay 60000 [27892:27892:0419/113708.348660:23078814691:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000da30 [27892:27892:0419/113708.348686:23078814716:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.348738:23078814769:INFO:invalidation-client-core.cc(488)] Return client token = "" [27892:27892:0419/113708.348863:23078814895: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: "-669528170259921202" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [27892:27892:0419/113708.348987:23078815018:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000daf0 with delay 0 [27892:27892:0419/113708.349017:23078815048:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000daf0 [27892:27892:0419/113708.349127:23078815157:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-669528170259921202" 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" } } [27892:27892:0419/113708.349178:23078815209:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-669528170259921202" [27892:27892:0419/113708.349207:23078815238:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [27892:27892:0419/113708.349240:23078815271:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 40024 with a delay 1200000000, Now = 211419424 [27892:27892:0419/113708.349270:23078815301:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000db10 with delay 1200000 [27892:27892:0419/113708.349299:23078815333:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [27892:27892:0419/113708.349457:23078815489:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [27892:27892:0419/113708.349489:23078815520:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 67272 with a delay 0, Now = 211419424 [27892:27892:0419/113708.349521:23078815552:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000dd30 with delay 0 [27892:27892:0419/113708.349568:23078815600: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 [27892:27892:0419/113708.349605:23078815637:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000dd30 [27892:27892:0419/113708.349674:23078815705:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ddf0 with delay 0 [27892:27892:0419/113708.349720:23078815751:INFO:recurring-task.cc(55)] [Retry] Scheduling 67272 with a delay 10000000, Now = 211419424 [27892:27892:0419/113708.349758:23078815792:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000de30 with delay 10000 [27892:27892:0419/113708.349790:23078815820:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ddf0 [27892:27892:0419/113708.349818:23078815847:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [27892:27892:0419/113708.350121:23078816157:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000de30 [27892:27892:0419/113708.351025:23078817057:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000da50 [27892:27892:0419/113708.370528:23078836565:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x60200000db10 [27892:27892:0419/113708.370623:23078836654:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [27892:27892:0419/113708.370685:23078836716:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [27892:27892:0419/113708.370735:23078836766:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [27892:27892:0419/113708.370918:23078836950: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 } [27892:27892:0419/113708.370975:23078837006:INFO:recurring-task.cc(55)] [Send-info] Scheduling 238248 with a delay 500000, Now = 1411419424 [27892:27892:0419/113708.371013:23078837044:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000de50 with delay 500 [27892:27892:0419/113708.371051:23078837081:INFO:recurring-task.cc(55)] [Retry] Scheduling 40024 with a delay 1200000000, Now = 1411419424 [27892:27892:0419/113708.371081:23078837112:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000de70 with delay 1200000 [27892:27892:0419/113708.371143:23078837175:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x60200000de50 [27892:27892:0419/113708.371172:23078837203:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.371241:23078837271:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [27892:27892:0419/113708.371270:23078837301:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [27892:27892:0419/113708.371497:23078837539: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 (27 ms) [28/28] InvalidationClientImplTest.Heartbeats (27 ms) SUCCESS: all tests passed. Tests took 0 seconds. 2019-04-20 11:26:42,618 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmpVH3C9N/4454d066de0cb510'] 2019-04-20 11:26:42,618 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmpVH3C9N/4454d066de0cb510/output.json'] 2019-04-20 11:26:42,618 - root: [INFO] merge_cmd: /b/swarming/w/ir/cache/vpython/ba947a/bin/python /b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --build-properties {"blamelist": ["chromium-internal-autoroll@skia-corp.google.com.iam.gserviceaccount.com"], "bot_id": "swarm2794-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:5071639625-1lppvbtck1morgivc6sq4dul7klu27sd@developer.gserviceaccount.com", "created_ts": 1555783159564784, "id": "8915636833635380432", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_asan_rel_ng/258848", "builder:linux_chromium_asan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1576210/2", "cq_experimental:false", "user_agent:cq"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_asan_rel_ng", "buildnumber": 258848, "category": "cq", "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "3d7996b3a914b260c21eebcf9e7957344fd1e03f", "got_revision_cp": "refs/heads/master@{#652771}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1576210, "patch_project": "chromium/src", "patch_ref": "refs/changes/10/1576210/2", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 2, "patch_storage": "gerrit", "path_config": "generic", "reason": "CQ", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src", "revision": "HEAD"} --summary-json /b/swarming/w/ir/tmp/t/tmpbMtlgc.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpVH3C9N -o /b/swarming/w/ir/tmp/t/tmp6V3RlW.json /b/swarming/w/ir/tmp/t/tmpVH3C9N/4454d066de0cb510/output.json Running ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"blamelist": ["chromium-internal-autoroll@skia-corp.google.com.iam.gserviceaccount.com"], "bot_id": "swarm2794-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:5071639625-1lppvbtck1morgivc6sq4dul7klu27sd@developer.gserviceaccount.com", "created_ts": 1555783159564784, "id": "8915636833635380432", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_asan_rel_ng/258848", "builder:linux_chromium_asan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1576210/2", "cq_experimental:false", "user_agent:cq"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_asan_rel_ng", "buildnumber": 258848, "category": "cq", "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "3d7996b3a914b260c21eebcf9e7957344fd1e03f", "got_revision_cp": "refs/heads/master@{#652771}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1576210, "patch_project": "chromium/src", "patch_ref": "refs/changes/10/1576210/2", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 2, "patch_storage": "gerrit", "path_config": "generic", "reason": "CQ", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src", "revision": "HEAD"}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpbMtlgc.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpVH3C9N', '-o', '/b/swarming/w/ir/tmp/t/tmp6V3RlW.json', '/b/swarming/w/ir/tmp/t/tmpVH3C9N/4454d066de0cb510/output.json'] in None (env: None) Command ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"blamelist": ["chromium-internal-autoroll@skia-corp.google.com.iam.gserviceaccount.com"], "bot_id": "swarm2794-c4", "buildbucket": {"build": {"bucket": "luci.chromium.try", "created_by": "user:5071639625-1lppvbtck1morgivc6sq4dul7klu27sd@developer.gserviceaccount.com", "created_ts": 1555783159564784, "id": "8915636833635380432", "project": "chromium", "tags": ["build_address:luci.chromium.try/linux_chromium_asan_rel_ng/258848", "builder:linux_chromium_asan_rel_ng", "buildset:patch/gerrit/chromium-review.googlesource.com/1576210/2", "cq_experimental:false", "user_agent:cq"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "linux_chromium_asan_rel_ng", "buildnumber": 258848, "category": "cq", "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "3d7996b3a914b260c21eebcf9e7957344fd1e03f", "got_revision_cp": "refs/heads/master@{#652771}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "tryserver.chromium.linux", "patch_gerrit_url": "https://chromium-review.googlesource.com", "patch_issue": 1576210, "patch_project": "chromium/src", "patch_ref": "refs/changes/10/1576210/2", "patch_repository_url": "https://chromium.googlesource.com/chromium/src", "patch_set": 2, "patch_storage": "gerrit", "path_config": "generic", "reason": "CQ", "recipe": "chromium_trybot", "repository": "https://chromium.googlesource.com/chromium/src", "revision": "HEAD"}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpbMtlgc.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpVH3C9N', '-o', '/b/swarming/w/ir/tmp/t/tmp6V3RlW.json', '/b/swarming/w/ir/tmp/t/tmpVH3C9N/4454d066de0cb510/output.json'] returned exit code 0