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/swarming/resources/collect_task.py --verbose -o /b/swarming/w/ir/tmp/t/tmpRT7R4H.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpQNM1TS --merge-script /b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/swarming/resources/standard_gtest_merge.py --merge-script-stdout-file /b/swarming/w/ir/tmp/t/tmp19BgGSmerge_script_log --merge-additional-args '[]' --build-properties '{"bot_id": "swarm2372-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "user:luci-scheduler@appspot.gserviceaccount.com", "created_ts": 1550980359589551, "id": "8920672934421803088", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux MSan Tests/15179", "builder:Linux MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "gitiles_ref:refs/heads/master", "parent_buildername:Linux MSan Builder", "parent_buildnumber:17448", "scheduler_invocation_id:9086102996586304176", "scheduler_job_id:chromium/Linux MSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux MSan Tests", "buildnumber": 15179, "got_angle_revision": "f78131dac0763e4c2d1310a9560cbd311e5dea64", "got_dawn_revision": "87bf834109fd5d372e62901101f285d4fb65fe67", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "got_revision_cp": "refs/heads/master@{#634985}", "got_swarming_client_revision": "d50a88f50782ba29076061b94c7b9d08a6c7e424", "got_v8_revision": "2f408608876b015b5c40977a6e3bf3984ce8cbe8", "got_v8_revision_cp": "refs/heads/7.4.207@{#1}", "got_webrtc_revision": "8721bb30d86d400a81c9b994e0e1a34a45e7e77b", "got_webrtc_revision_cp": "refs/heads/master@{#26825}", "mastername": "chromium.memory", "parent_buildername": "Linux MSan Builder", "parent_got_angle_revision": "f78131dac0763e4c2d1310a9560cbd311e5dea64", "parent_got_dawn_revision": "87bf834109fd5d372e62901101f285d4fb65fe67", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "parent_got_revision_cp": "refs/heads/master@{#634985}", "parent_got_swarming_client_revision": "d50a88f50782ba29076061b94c7b9d08a6c7e424", "parent_got_v8_revision": "2f408608876b015b5c40977a6e3bf3984ce8cbe8", "parent_got_v8_revision_cp": "refs/heads/7.4.207@{#1}", "parent_got_webrtc_revision": "8721bb30d86d400a81c9b994e0e1a34a45e7e77b", "parent_got_webrtc_revision_cp": "refs/heads/master@{#26825}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "swarm_hashes": {"accessibility_unittests": "90bbd359d293244647b6945aed752269a1c74543", "angle_unittests": "40a95d65697fc6014cefd698641bf85a74ff3364", "app_shell_unittests": "a35f35c1f5c1714e8037b479390f97d5dd5c8ddf", "aura_unittests": "db6a27a0ae59005c1f435497342bddd5aff7e511", "base_unittests": "548103e04b38b08c3fb3e2562a301d9e71023ccb", "blink_common_unittests": "b05926a8311e85c1600d44b0d382cdf3228e4264", "blink_fuzzer_unittests": "65a11bdf6e2d09db13bde094583e996425422174", "blink_heap_unittests": "a635ba0044fee7c8059076fc21631dd9b2e93cb1", "blink_platform_unittests": "fd6cdcec71de25b73efb700201c2ea3355266bbd", "blink_unittests": "1bc89b758cd719b8c8382345159bb63a85aab134", "boringssl_crypto_tests": "46efeae8d7d0ab5da926529e0312c4f4b53bd753", "boringssl_ssl_tests": "0e94168488e5a6fbaa902424cf945008172a8d9f", "browser_tests": "5b4f162529c163e86039d5928b7a29247cfafcd4", "cacheinvalidation_unittests": "770199c099aa65fd3b11986ba5f9e537f73abb6f", "capture_unittests": "c847615a4f08d250db7a8083701e930f0bd93368", "cast_unittests": "52d2b130879283bb1cf51025f21bb016ac860ea6", "cc_unittests": "69c1c96f053dd9ac740814249eaa3052fce19b6f", "chrome_app_unittests": "bd6708ff6775a787a94b1804495b3964beba6600", "chromedriver_unittests": "85e07b07ae5fdabd694c905b8927cf257cdb5f3f", "components_browsertests": "492a00938dcae8cb412cd7febfe790c9caf91ef6", "components_unittests": "af47f66ba16432484d8803776be6902736938b70", "compositor_unittests": "fc75840984122747a3542e4914eca0909a2e7cf1", "content_browsertests": "0ce43d7dfd6182b74887564f25e6dc291f21e347", "content_unittests": "83094c2109a4389c8b8d3d6a8d5886a0763a1062", "cronet_tests": "70f62a590fa2723349e507654e4dd67814686c76", "cronet_unittests": "9a976839c420c9b1c0967743d6a4f0140ffcfd3c", "crypto_unittests": "2ae959e43142f1a7165561bca532dcdfe52dfe96", "dbus_unittests": "28453e90b321a2c5afacb6e91e9ad83099e53c15", "device_unittests": "8bddd84790afbdfbec2acb24fe3ea4530e388058", "display_unittests": "f9ef06e042d6997f75ec019f812d4d3d29ad80c9", "events_unittests": "edefa705b88e4e6c7ae4128dce4e4f4a4f494e8d", "extensions_browsertests": "41d1e03a1ff711ba793e3ea2b163d47ee7c61b09", "extensions_unittests": "9b422727ae90514586ab6ca7a0618b6d53d1700f", "filesystem_service_unittests": "0cb638ea21f3cb25c6619b89a10f25abc5441fd8", "gcm_unit_tests": "e0f48c4ba3f4ba13edff836ac8735bd6a8a7d48c", "gfx_unittests": "926ab7ec3040d30cec5d8f0d83ff86a784bf5d0a", "gin_unittests": "51fd7923436d5f507bf717a1ea3e10a425709609", "gl_unittests": "4430054f1e06739b53a46cbd4ab9808d0bed26c2", "google_apis_unittests": "78d0ee01512abbc63dfdd16065684f10f1890a87", "gpu_unittests": "2e77f6c4c448bfc31708c8ff4523e59d3eee8ac9", "headless_browsertests": "24472f0157389af7b7d911ca4021609d6c6e2bf1", "headless_unittests": "d03a9b5c4a42ea34d6a894037ffad5e9e095569a", "interactive_ui_tests": "ae27269f6e5ffb394f181ff377807cd4e58db37c", "ipc_tests": "ec90b18191c09014aabf6f2226c071a8962d1c15", "jingle_unittests": "4c322fae7aceb37a2101a8cad4300758e550fb6a", "latency_unittests": "2868adeb258e67d3a76bccd283b91d2c686a3599", "leveldb_service_unittests": "0e8a9c7c1dfd57d06aadf5c9de6038f8d4c9352f", "libjingle_xmpp_unittests": "8ef6e50e2e4dc333ca8884dc54232e2b0e9e9069", "media_blink_unittests": "a2aa9a5e767b5a9ffb0e126e7c335be59f1bd911", "media_service_unittests": "0f6498294bc41993507f50d3fe9c9ec6a110b4ee", "media_unittests": "8dad22d953f1071e5abd8b7f2a1517c64772d6da", "message_center_unittests": "d4b5e24c980e4a323885726dedddd3d1db893482", "midi_unittests": "6e18d97ba4890fb1f01921973296660dbc761de1", "mojo_core_unittests": "f1673b79b29f075a2793dc31cac29e71b5acb6dd", "mojo_unittests": "c0e19e8e7847fb65a60ea511a5968940684b0b36", "nacl_helper_nonsfi_unittests": "0d861f9fb2d6adde53388df86a65de07890d79c2", "nacl_loader_unittests": "19edec03d0a53ce71e8c7ea36d33c15965ea05ec", "native_theme_unittests": "6d10d1913a21926d6a1d96d8f85192b0087344be", "net_unittests": "d1f8234a14d5041d68583d6c4ea852faebf204ca", "pdf_unittests": "ce5d5679da7c3bf2c192732cbbdcfb2e86b4ef78", "ppapi_unittests": "b7e5da945d1aacd78716d275e207319a83dc36f2", "printing_unittests": "350bb5a373c5b5995a9f463d4c90db0286e4bbfc", "remoting_unittests": "30616f86fe250e7d79f9bfd5ca95550fe1b08e67", "sandbox_linux_unittests": "9ffb7c0b2a7c34773bbb23f21c52aac043eec64c", "service_manager_unittests": "023c2640bea2c2ff3283835394f7843611504aa6", "shell_dialogs_unittests": "c85719364c336ef6ed7b293ca26cb70837abcee7", "skia_unittests": "cfab406a21f83b631e82c16253e4aaa53cf4399f", "snapshot_unittests": "36790e36faffd70ed77c55fcabfd53a5bdde6fb5", "sql_unittests": "661da5b767d67d0a141f831b039616086156a96b", "storage_unittests": "efc190c569da8be94b7e75e4c16412773b9c140b", "sync_integration_tests": "a4b0da9a3c2bc600d11745305df76369eaa58252", "traffic_annotation_auditor_unittests": "f4384285fa084a3b5aeb6ef8c90e1222fd04bb05", "ui_base_unittests": "5f6e27bd982e78a3e558ff54fc9459dadd3e19c0", "ui_touch_selection_unittests": "088212858d2f07004fe6cf7f94be87b5869ad445", "unit_tests": "aa7cb15a5661973275e07892cc9648ad14b48bad", "url_unittests": "bbdfe2050b11961ac9fc990d279d4f19d79c26ac", "views_unittests": "c01deaf6915d5f120488973d178943cb81d40754", "viz_unittests": "8b72b198b734b027f409f816e16845a799162577", "vr_common_unittests": "e0ba97988008c3937e3c14187ed1c962e3678e33", "vr_pixeltests": "2c5a05b7fd40750721fac1ae20b28e27b003cb00", "wm_unittests": "dcb155506fd5ca35fb6fb67bc28f2736e568b937", "wtf_unittests": "0e0c40459abb4d40e8f57601218ea3e438ff884c"}}' --summary-json-file /b/swarming/w/ir/tmp/t/tmptIWyRX.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/tmpvWpZWy.json in dir /b/swarming/w/ir/k: allow_subannotations: True base_name: 'cacheinvalidation_unittests' 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/swarming/resources/collect_task.py', '--verbose', '-o', '/b/swarming/w/ir/tmp/t/tmpRT7R4H.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpQNM1TS', '--merge-script', '/b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/swarming/resources/standard_gtest_merge.py', '--merge-script-stdout-file', '/b/swarming/w/ir/tmp/t/tmp19BgGSmerge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"bot_id": "swarm2372-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "user:luci-scheduler@appspot.gserviceaccount.com", "created_ts": 1550980359589551, "id": "8920672934421803088", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux MSan Tests/15179", "builder:Linux MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "gitiles_ref:refs/heads/master", "parent_buildername:Linux MSan Builder", "parent_buildnumber:17448", "scheduler_invocation_id:9086102996586304176", "scheduler_job_id:chromium/Linux MSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux MSan Tests", "buildnumber": 15179, "got_angle_revision": "f78131dac0763e4c2d1310a9560cbd311e5dea64", "got_dawn_revision": "87bf834109fd5d372e62901101f285d4fb65fe67", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "got_revision_cp": "refs/heads/master@{#634985}", "got_swarming_client_revision": "d50a88f50782ba29076061b94c7b9d08a6c7e424", "got_v8_revision": "2f408608876b015b5c40977a6e3bf3984ce8cbe8", "got_v8_revision_cp": "refs/heads/7.4.207@{#1}", "got_webrtc_revision": "8721bb30d86d400a81c9b994e0e1a34a45e7e77b", "got_webrtc_revision_cp": "refs/heads/master@{#26825}", "mastername": "chromium.memory", "parent_buildername": "Linux MSan Builder", "parent_got_angle_revision": "f78131dac0763e4c2d1310a9560cbd311e5dea64", "parent_got_dawn_revision": "87bf834109fd5d372e62901101f285d4fb65fe67", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "parent_got_revision_cp": "refs/heads/master@{#634985}", "parent_got_swarming_client_revision": "d50a88f50782ba29076061b94c7b9d08a6c7e424", "parent_got_v8_revision": "2f408608876b015b5c40977a6e3bf3984ce8cbe8", "parent_got_v8_revision_cp": "refs/heads/7.4.207@{#1}", "parent_got_webrtc_revision": "8721bb30d86d400a81c9b994e0e1a34a45e7e77b", "parent_got_webrtc_revision_cp": "refs/heads/master@{#26825}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "swarm_hashes": {"accessibility_unittests": "90bbd359d293244647b6945aed752269a1c74543", "angle_unittests": "40a95d65697fc6014cefd698641bf85a74ff3364", "app_shell_unittests": "a35f35c1f5c1714e8037b479390f97d5dd5c8ddf", "aura_unittests": "db6a27a0ae59005c1f435497342bddd5aff7e511", "base_unittests": "548103e04b38b08c3fb3e2562a301d9e71023ccb", "blink_common_unittests": "b05926a8311e85c1600d44b0d382cdf3228e4264", "blink_fuzzer_unittests": "65a11bdf6e2d09db13bde094583e996425422174", "blink_heap_unittests": "a635ba0044fee7c8059076fc21631dd9b2e93cb1", "blink_platform_unittests": "fd6cdcec71de25b73efb700201c2ea3355266bbd", "blink_unittests": "1bc89b758cd719b8c8382345159bb63a85aab134", "boringssl_crypto_tests": "46efeae8d7d0ab5da926529e0312c4f4b53bd753", "boringssl_ssl_tests": "0e94168488e5a6fbaa902424cf945008172a8d9f", "browser_tests": "5b4f162529c163e86039d5928b7a29247cfafcd4", "cacheinvalidation_unittests": "770199c099aa65fd3b11986ba5f9e537f73abb6f", "capture_unittests": "c847615a4f08d250db7a8083701e930f0bd93368", "cast_unittests": "52d2b130879283bb1cf51025f21bb016ac860ea6", "cc_unittests": "69c1c96f053dd9ac740814249eaa3052fce19b6f", "chrome_app_unittests": "bd6708ff6775a787a94b1804495b3964beba6600", "chromedriver_unittests": "85e07b07ae5fdabd694c905b8927cf257cdb5f3f", "components_browsertests": "492a00938dcae8cb412cd7febfe790c9caf91ef6", "components_unittests": "af47f66ba16432484d8803776be6902736938b70", "compositor_unittests": "fc75840984122747a3542e4914eca0909a2e7cf1", "content_browsertests": "0ce43d7dfd6182b74887564f25e6dc291f21e347", "content_unittests": "83094c2109a4389c8b8d3d6a8d5886a0763a1062", "cronet_tests": "70f62a590fa2723349e507654e4dd67814686c76", "cronet_unittests": "9a976839c420c9b1c0967743d6a4f0140ffcfd3c", "crypto_unittests": "2ae959e43142f1a7165561bca532dcdfe52dfe96", "dbus_unittests": "28453e90b321a2c5afacb6e91e9ad83099e53c15", "device_unittests": "8bddd84790afbdfbec2acb24fe3ea4530e388058", "display_unittests": "f9ef06e042d6997f75ec019f812d4d3d29ad80c9", "events_unittests": "edefa705b88e4e6c7ae4128dce4e4f4a4f494e8d", "extensions_browsertests": "41d1e03a1ff711ba793e3ea2b163d47ee7c61b09", "extensions_unittests": "9b422727ae90514586ab6ca7a0618b6d53d1700f", "filesystem_service_unittests": "0cb638ea21f3cb25c6619b89a10f25abc5441fd8", "gcm_unit_tests": "e0f48c4ba3f4ba13edff836ac8735bd6a8a7d48c", "gfx_unittests": "926ab7ec3040d30cec5d8f0d83ff86a784bf5d0a", "gin_unittests": "51fd7923436d5f507bf717a1ea3e10a425709609", "gl_unittests": "4430054f1e06739b53a46cbd4ab9808d0bed26c2", "google_apis_unittests": "78d0ee01512abbc63dfdd16065684f10f1890a87", "gpu_unittests": "2e77f6c4c448bfc31708c8ff4523e59d3eee8ac9", "headless_browsertests": "24472f0157389af7b7d911ca4021609d6c6e2bf1", "headless_unittests": "d03a9b5c4a42ea34d6a894037ffad5e9e095569a", "interactive_ui_tests": "ae27269f6e5ffb394f181ff377807cd4e58db37c", "ipc_tests": "ec90b18191c09014aabf6f2226c071a8962d1c15", "jingle_unittests": "4c322fae7aceb37a2101a8cad4300758e550fb6a", "latency_unittests": "2868adeb258e67d3a76bccd283b91d2c686a3599", "leveldb_service_unittests": "0e8a9c7c1dfd57d06aadf5c9de6038f8d4c9352f", "libjingle_xmpp_unittests": "8ef6e50e2e4dc333ca8884dc54232e2b0e9e9069", "media_blink_unittests": "a2aa9a5e767b5a9ffb0e126e7c335be59f1bd911", "media_service_unittests": "0f6498294bc41993507f50d3fe9c9ec6a110b4ee", "media_unittests": "8dad22d953f1071e5abd8b7f2a1517c64772d6da", "message_center_unittests": "d4b5e24c980e4a323885726dedddd3d1db893482", "midi_unittests": "6e18d97ba4890fb1f01921973296660dbc761de1", "mojo_core_unittests": "f1673b79b29f075a2793dc31cac29e71b5acb6dd", "mojo_unittests": "c0e19e8e7847fb65a60ea511a5968940684b0b36", "nacl_helper_nonsfi_unittests": "0d861f9fb2d6adde53388df86a65de07890d79c2", "nacl_loader_unittests": "19edec03d0a53ce71e8c7ea36d33c15965ea05ec", "native_theme_unittests": "6d10d1913a21926d6a1d96d8f85192b0087344be", "net_unittests": "d1f8234a14d5041d68583d6c4ea852faebf204ca", "pdf_unittests": "ce5d5679da7c3bf2c192732cbbdcfb2e86b4ef78", "ppapi_unittests": "b7e5da945d1aacd78716d275e207319a83dc36f2", "printing_unittests": "350bb5a373c5b5995a9f463d4c90db0286e4bbfc", "remoting_unittests": "30616f86fe250e7d79f9bfd5ca95550fe1b08e67", "sandbox_linux_unittests": "9ffb7c0b2a7c34773bbb23f21c52aac043eec64c", "service_manager_unittests": "023c2640bea2c2ff3283835394f7843611504aa6", "shell_dialogs_unittests": "c85719364c336ef6ed7b293ca26cb70837abcee7", "skia_unittests": "cfab406a21f83b631e82c16253e4aaa53cf4399f", "snapshot_unittests": "36790e36faffd70ed77c55fcabfd53a5bdde6fb5", "sql_unittests": "661da5b767d67d0a141f831b039616086156a96b", "storage_unittests": "efc190c569da8be94b7e75e4c16412773b9c140b", "sync_integration_tests": "a4b0da9a3c2bc600d11745305df76369eaa58252", "traffic_annotation_auditor_unittests": "f4384285fa084a3b5aeb6ef8c90e1222fd04bb05", "ui_base_unittests": "5f6e27bd982e78a3e558ff54fc9459dadd3e19c0", "ui_touch_selection_unittests": "088212858d2f07004fe6cf7f94be87b5869ad445", "unit_tests": "aa7cb15a5661973275e07892cc9648ad14b48bad", "url_unittests": "bbdfe2050b11961ac9fc990d279d4f19d79c26ac", "views_unittests": "c01deaf6915d5f120488973d178943cb81d40754", "viz_unittests": "8b72b198b734b027f409f816e16845a799162577", "vr_common_unittests": "e0ba97988008c3937e3c14187ed1c962e3678e33", "vr_pixeltests": "2c5a05b7fd40750721fac1ae20b28e27b003cb00", "wm_unittests": "dcb155506fd5ca35fb6fb67bc28f2736e568b937", "wtf_unittests": "0e0c40459abb4d40e8f57601218ea3e438ff884c"}}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmptIWyRX.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/tmpvWpZWy.json'] env: {'CHROME_HEADLESS': '1'} env_prefixes: {'PATH': '/b/swarming/w/ir/cache/swarming_client'} env_suffixes: {} infra_step: False name: 'cacheinvalidation_unittests' nest_level: 0 ok_ret: frozenset([0]) step_test_data: <lambda>(...) trigger_specs: () full environment: ADDRFAM: inet BOTO_CONFIG: /b/swarming/w/ir/tmp/gsutil_task/.boto BUILDBUCKET_EXPERIMENTAL: FALSE CHROME_HEADLESS: 1 CIPD_CACHE_DIR: /b/swarming/cipd_cache/cache CIPD_PROTOCOL: v2 DEVSHELL_CLIENT_PORT: 40872 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/8920672934421803088 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/it4UJGaF/luci_context.191507621 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: swarm2372-c4 SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 433673b0cef82b11 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-02-23 20:00:11,171 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmpQNM1TS' 2019-02-23 20:00:11,171 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmpQNM1TS' already exists! 2019-02-23 20:00:11,171 - root: [WARNING] task_output_dir existing content: [] 2019-02-23 20:00:11,171 - 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/tmpvWpZWy.json -output-dir /b/swarming/w/ir/tmp/t/tmpQNM1TS -task-summary-json /b/swarming/w/ir/tmp/t/tmptIWyRX.json [D2019-02-23T20:00:11.177445-08:00 1799 0 auth.go:1265] Minting a new token {"key":"luci_ctx/afeada4c4c4ade83796f05350ae9f6f53c578f7a6cb54534992183c420de34a2", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-02-23T20:00:11.177504-08:00 1799 0 luci_ctx.go:138] POST http://127.0.0.1:37285/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/afeada4c4c4ade83796f05350ae9f6f53c578f7a6cb54534992183c420de34a2", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-02-23T20:00:11.179050-08:00 1799 0 auth.go:1222] Token expires in 8m30.820968614s {"key":"luci_ctx/afeada4c4c4ade83796f05350ae9f6f53c578f7a6cb54534992183c420de34a2", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 433676236eaca410: exit 0 Additional test environment: CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox CHROME_HEADLESS=1 G_SLICE=always-malloc LANG=en_US.UTF-8 LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer MSAN_OPTIONS=symbolize=0 NSS_DISABLE_ARENA_FREE_LIST=1 NSS_DISABLE_UNLOAD=1 Command: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioj93iOf/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 [16101:16101:0222/175332.489749:16402350900:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000012a0 with delay 0 [16101:16101:0222/175332.490047:16402351192:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000012a0 [16101:16101:0222/175332.490376:16402351523: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 } [16101:16101:0222/175332.490440:16402351587:INFO:recurring-task.cc(55)] [Startup] Scheduling 9224 with a delay 500000, Now = 210919424 [16101:16101:0222/175332.490489:16402351636:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001330 with delay 500 [16101:16101:0222/175332.490555:16402351712:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001330 [16101:16101:0222/175332.490832:16402351978:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "unit-test-nonce" application_client_id: { client_type: 2 client_name: "unit-test-client-id" } digest_serialization_type: BYTE_BASED } } [ OK ] ProtocolHandlerTest.SendInitializeOnly (2 ms) [1/28] ProtocolHandlerTest.SendInitializeOnly (2 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [16101:16101:0222/175332.491954:16402353099: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 [16101:16101:0222/175332.492402:16402353549:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001230 with delay 0 [16101:16101:0222/175332.492490:16402353638:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001260 with delay 0 [16101:16101:0222/175332.492548:16402353694:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000011e0 with delay 0 [16101:16101:0222/175332.492613:16402353756:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001220 with delay 0 [16101:16101:0222/175332.492648:16402353790:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000011d0 with delay 0 [16101:16101:0222/175332.492693:16402353837:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001210 with delay 0 [16101:16101:0222/175332.493023:16402354167:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001230 [16101:16101:0222/175332.493154:16402354298: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 } [16101:16101:0222/175332.493211:16402354355:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9320 with a delay 500000, Now = 210919424 [16101:16101:0222/175332.493253:16402354396:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001380 with delay 500 [16101:16101:0222/175332.493296:16402354438:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001260 [16101:16101:0222/175332.493334:16402354476:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000011e0 [16101:16101:0222/175332.493367:16402354509:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001220 [16101:16101:0222/175332.493404:16402354546:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000011d0 [16101:16101:0222/175332.493438:16402354579:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001210 [16101:16101:0222/175332.493493:16402354637:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [16101:16101:0222/175332.493558:16402354701:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001380 [16101:16101:0222/175332.493696:16402354842:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [16101:16101:0222/175332.494046:16402355191:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } registration_message: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } registration: { object_id: { source: 2 name: "oid1" } op_type: UNREGISTER } registration: { object_id: { source: 2 name: "oid2" } op_type: UNREGISTER } } registration_sync_message: { subtree: { registered_object: { source: 2 name: "oid0" } } } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "unit-test" } performance_counter: { name: "x" value: 3 } performance_counter: { name: "y" value: 81 } server_registration_summary_requested: true } } [ OK ] ProtocolHandlerTest.SendMultipleMessageTypes (3 ms) [3/28] ProtocolHandlerTest.SendMultipleMessageTypes (3 ms) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage [16101:16101:0222/175332.495685:16402356830: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 (0 ms) [4/28] ProtocolHandlerTest.IncomingCompositeMessage (0 ms) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage [16101:16101:0222/175332.496283:16402357430: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 } } [16101:16101:0222/175332.496365:16402357509: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" } [16101:16101:0222/175332.496455:16402357599: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 } } [16101:16101:0222/175332.496562:16402357708: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 (0 ms) [5/28] ProtocolHandlerTest.InvalidInboundMessage (0 ms) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch [16101:16101:0222/175332.497044:16402358188: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 } } [16101:16101:0222/175332.497158:16402358302:ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } [ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms) [6/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch [16101:16101:0222/175332.497642:16402358787: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 [16101:16101:0222/175332.498126:16402359271: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" } } [16101:16101:0222/175332.498191:16402359335:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001160 with delay 0 [16101:16101:0222/175332.498228:16402359374:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001160 [16101:16101:0222/175332.498312:16402359458: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 } [16101:16101:0222/175332.498365:16402359508:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9704 with a delay 500000, Now = 210919424 [16101:16101:0222/175332.498406:16402359550:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001170 with delay 500 [16101:16101:0222/175332.498457:16402359600:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001170 [16101:16101:0222/175332.498495:16402359639:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 [ OK ] ProtocolHandlerTest.ConfigMessage (47 ms) [8/28] ProtocolHandlerTest.ConfigMessage (47 ms) [ RUN ] ProtocolHandlerTest.ErrorMessage [16101:16101:0222/175332.545131:16402406277: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 [16101:16101:0222/175332.545663:16402406807: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 ] InvalidationClientImplTest.Start [16100:16100:0222/175332.449676:16402310832:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001990 with delay 0 [16100:16100:0222/175332.450028:16402311178:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [16100:16100:0222/175332.450362:16402311512:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d20 with delay 0 [16100:16100:0222/175332.450415:16402311559:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001990 [16100:16100:0222/175332.450455:16402311598:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d20 [16100:16100:0222/175332.450557:16402311710:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [16100:16100:0222/175332.450670:16402311815:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001ca0 with delay 0 [16100:16100:0222/175332.450723:16402311866:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001ca0 [16100:16100:0222/175332.450761:16402311905:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [16100:16100:0222/175332.450804:16402311955:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d20 with delay 0 [16100:16100:0222/175332.450851:16402311993:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d20 [16100:16100:0222/175332.450909:16402312058:INFO:invalidation-client-core.cc(351)] Starting with no previous state [16100:16100:0222/175332.450974:16402312122:INFO:recurring-task.cc(55)] [Startup] Scheduling 9320 with a delay 0, Now = 210919424 [16100:16100:0222/175332.451022:16402312171:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001ca0 with delay 0 [16100:16100:0222/175332.451074:16402312216:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001ca0 [16100:16100:0222/175332.451166:16402312310:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1347132497555207870" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [16100:16100:0222/175332.451216:16402312360:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9416 with a delay 500000, Now = 210919424 [16100:16100:0222/175332.451260:16402312406:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d20 with delay 500 [16100:16100:0222/175332.451299:16402312445:INFO:recurring-task.cc(55)] [Retry] Scheduling 9320 with a delay 60000000, Now = 210919424 [16100:16100:0222/175332.451338:16402312486:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d40 with delay 60000 [16100:16100:0222/175332.451395:16402312539:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001d20 [16100:16100:0222/175332.451442:16402312600:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.451526:16402312680:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.451708:16402312858: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: "1347132497555207870" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [16100:16100:0222/175332.451905:16402313053:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001d20 with delay 0 [16100:16100:0222/175332.451963:16402313107:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001d20 [16100:16100:0222/175332.452125:16402313274:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1347132497555207870" 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" } } [16100:16100:0222/175332.452207:16402313352:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1347132497555207870" [16100:16100:0222/175332.452254:16402313399:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [16100:16100:0222/175332.452297:16402313441:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [16100:16100:0222/175332.452341:16402313493:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001cf0 with delay 1200000 [16100:16100:0222/175332.452391:16402313537:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [16100:16100:0222/175332.452583:16402313728:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [16100:16100:0222/175332.452634:16402313782:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2440 with a delay 0, Now = 211419424 [16100:16100:0222/175332.452685:16402313829:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001ca0 with delay 0 [16100:16100:0222/175332.452759:16402313903: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 [16100:16100:0222/175332.452810:16402313953:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001ca0 [16100:16100:0222/175332.452890:16402314044:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001cc0 with delay 0 [16100:16100:0222/175332.452954:16402314098:INFO:recurring-task.cc(55)] [Retry] Scheduling 2440 with a delay 10000000, Now = 211419424 [16100:16100:0222/175332.453004:16402314155:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001990 with delay 10000 [16100:16100:0222/175332.453050:16402314192:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001cc0 [16100:16100:0222/175332.453088:16402314235:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (5 ms) [11/28] InvalidationClientImplTest.Start (5 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [16100:16100:0222/175332.453815:16402314960:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d10 with delay 0 [16100:16100:0222/175332.453882:16402315025:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [ OK ] InvalidationClientImplTest.GenerateNonce (1 ms) [12/28] InvalidationClientImplTest.GenerateNonce (1 ms) [ RUN ] InvalidationClientImplTest.Register [16100:16100:0222/175332.454392:16402315536:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d00 with delay 0 [16100:16100:0222/175332.454454:16402315597:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [16100:16100:0222/175332.454754:16402315903:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c80 with delay 0 [16100:16100:0222/175332.454810:16402315954:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d00 [16100:16100:0222/175332.454847:16402315990:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001c80 [16100:16100:0222/175332.454956:16402316101:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [16100:16100:0222/175332.455026:16402316170:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001b00 with delay 0 [16100:16100:0222/175332.455070:16402316213:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001b00 [16100:16100:0222/175332.455105:16402316254:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [16100:16100:0222/175332.455152:16402316297:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c80 with delay 0 [16100:16100:0222/175332.455192:16402316335:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001c80 [16100:16100:0222/175332.455227:16402316377:INFO:invalidation-client-core.cc(351)] Starting with no previous state [16100:16100:0222/175332.455279:16402316423:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424 [16100:16100:0222/175332.455329:16402316473:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001b00 with delay 0 [16100:16100:0222/175332.455367:16402316510:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001b00 [16100:16100:0222/175332.455448:16402316595:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "3851513723501218264" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [16100:16100:0222/175332.455493:16402316642:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9320 with a delay 500000, Now = 210919424 [16100:16100:0222/175332.455553:16402316697:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c80 with delay 500 [16100:16100:0222/175332.455596:16402316739:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424 [16100:16100:0222/175332.455642:16402316786:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c60 with delay 60000 [16100:16100:0222/175332.455697:16402316844:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001c80 [16100:16100:0222/175332.455744:16402316891:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.455804:16402316948:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.455946:16402317095: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: "3851513723501218264" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [16100:16100:0222/175332.456082:16402317231:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c80 with delay 0 [16100:16100:0222/175332.456131:16402317274:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001c80 [16100:16100:0222/175332.456264:16402317417:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "3851513723501218264" 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" } } [16100:16100:0222/175332.456343:16402317491:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "3851513723501218264" [16100:16100:0222/175332.456394:16402317540:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [16100:16100:0222/175332.456448:16402317600:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [16100:16100:0222/175332.456500:16402317651:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001b10 with delay 1200000 [16100:16100:0222/175332.456564:16402317709:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [16100:16100:0222/175332.456708:16402317852:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [16100:16100:0222/175332.456756:16402317900:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 2056 with a delay 0, Now = 211419424 [16100:16100:0222/175332.456794:16402317940:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001b00 with delay 0 [16100:16100:0222/175332.456852:16402317996: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 [16100:16100:0222/175332.456906:16402318049:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001b00 [16100:16100:0222/175332.456978:16402318121:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001970 with delay 0 [16100:16100:0222/175332.457024:16402318168:INFO:recurring-task.cc(55)] [Retry] Scheduling 2056 with a delay 10000000, Now = 211419424 [16100:16100:0222/175332.457068:16402318212:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001d00 with delay 10000 [16100:16100:0222/175332.457118:16402318261:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001970 [16100:16100:0222/175332.457152:16402318300:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [16100:16100:0222/175332.457252:16402318400:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001970 with delay 0 [16100:16100:0222/175332.457297:16402318446:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000001970 [16100:16100:0222/175332.457357:16402318506:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [16100:16100:0222/175332.457410:16402318552:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [16100:16100:0222/175332.457453:16402318595:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [16100:16100:0222/175332.457535:16402318692:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9320 with a delay 500000, Now = 211469424 [16100:16100:0222/175332.457593:16402318736:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001b00 with delay 500 [16100:16100:0222/175332.457633:16402318777:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9704 with a delay 60000000, Now = 211469424 [16100:16100:0222/175332.457675:16402318818:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001b90 with delay 60000 [16100:16100:0222/175332.457732:16402318880:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000001b00 [16100:16100:0222/175332.457778:16402318926:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.457844:16402318988:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.457883:16402319030:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [16100:16100:0222/175332.458062:16402319206: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 } } } [16100:16100:0222/175332.458168:16402319316:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.458260:16402319410:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000001b00 with delay 0 [16100:16100:0222/175332.458309:16402319452:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000001b00 [16100:16100:0222/175332.458556:16402319706: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 } } } } [16100:16100:0222/175332.458661:16402319813: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 [16100:16100:0222/175332.458770:16402319914:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [16100:16100:0222/175332.458922:16402320065:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [16100:16100:0222/175332.459015:16402320157:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [16100:16100:0222/175332.459311:16402320463:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000001d00 [ OK ] InvalidationClientImplTest.Register (6 ms) [13/28] InvalidationClientImplTest.Register (6 ms) [ RUN ] InvalidationClientImplTest.Invalidations [16100:16100:0222/175332.460917:16402322061:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001dc0 with delay 0 [16100:16100:0222/175332.460987:16402322130:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [16100:16100:0222/175332.461327:16402322472:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001eb0 with delay 0 [16100:16100:0222/175332.461370:16402322517:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001dc0 [16100:16100:0222/175332.461410:16402322552:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001eb0 [16100:16100:0222/175332.461480:16402322632:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [16100:16100:0222/175332.461566:16402322711:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001970 with delay 0 [16100:16100:0222/175332.461613:16402322756:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001970 [16100:16100:0222/175332.461647:16402322796:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [16100:16100:0222/175332.461699:16402322843:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001eb0 with delay 0 [16100:16100:0222/175332.461738:16402322881:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001eb0 [16100:16100:0222/175332.461772:16402322920:INFO:invalidation-client-core.cc(351)] Starting with no previous state [16100:16100:0222/175332.461819:16402322969:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424 [16100:16100:0222/175332.461865:16402323016:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001970 with delay 0 [16100:16100:0222/175332.461911:16402323054:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001970 [16100:16100:0222/175332.461986:16402323129:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "863662551842817393" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [16100:16100:0222/175332.462039:16402323183:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424 [16100:16100:0222/175332.462083:16402323240:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001eb0 with delay 500 [16100:16100:0222/175332.462141:16402323285:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424 [16100:16100:0222/175332.462178:16402323330:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001fb0 with delay 60000 [16100:16100:0222/175332.462237:16402323388:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001eb0 [16100:16100:0222/175332.462283:16402323427:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.462330:16402323476:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.462469:16402323617: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: "863662551842817393" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [16100:16100:0222/175332.462600:16402323753:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001eb0 with delay 0 [16100:16100:0222/175332.462650:16402323795:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001eb0 [16100:16100:0222/175332.462770:16402323919:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "863662551842817393" 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" } } [16100:16100:0222/175332.462831:16402323980:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "863662551842817393" [16100:16100:0222/175332.462894:16402324038:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [16100:16100:0222/175332.462948:16402324098:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424 [16100:16100:0222/175332.463002:16402324151:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c80 with delay 1200000 [16100:16100:0222/175332.463051:16402324195:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [16100:16100:0222/175332.463168:16402324318:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [16100:16100:0222/175332.463222:16402324366:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1928 with a delay 0, Now = 211419424 [16100:16100:0222/175332.463261:16402324410:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001970 with delay 0 [16100:16100:0222/175332.463326:16402324472: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 [16100:16100:0222/175332.463375:16402324518:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001970 [16100:16100:0222/175332.463444:16402324587:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c50 with delay 0 [16100:16100:0222/175332.463490:16402324633:INFO:recurring-task.cc(55)] [Retry] Scheduling 1928 with a delay 10000000, Now = 211419424 [16100:16100:0222/175332.463535:16402324695:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001dc0 with delay 10000 [16100:16100:0222/175332.463589:16402324732:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001c50 [16100:16100:0222/175332.463628:16402324775:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [16100:16100:0222/175332.463694:16402324838:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.463773:16402324917:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001c50 with delay 0 [16100:16100:0222/175332.463816:16402324963:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000001c50 [16100:16100:0222/175332.464047:16402325192: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 } } } [16100:16100:0222/175332.464137:16402325284: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 [16100:16100:0222/175332.464219:16402325377: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" } [16100:16100:0222/175332.464371:16402325514:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [16100:16100:0222/175332.464466:16402325608:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [16100:16100:0222/175332.464560:16402325704:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000001c50 with delay 0 [16100:16100:0222/175332.464601:16402325744:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000001970 with delay 0 [16100:16100:0222/175332.464637:16402325783:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000001af0 with delay 0 [16100:16100:0222/175332.464675:16402325823:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000001c50 [16100:16100:0222/175332.464737:16402325881:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9896 with a delay 500000, Now = 211519424 [16100:16100:0222/175332.464782:16402325930:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000001eb0 with delay 500 [16100:16100:0222/175332.464840:16402325982:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000001970 [16100:16100:0222/175332.464880:16402326022:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000001af0 [16100:16100:0222/175332.464930:16402326080:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x701000001eb0 [16100:16100:0222/175332.464976:16402326125:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.465041:16402326184:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.465080:16402326228:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [16100:16100:0222/175332.465273:16402326417: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) [14/28] InvalidationClientImplTest.Invalidations (5 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [16100:16100:0222/175332.465975:16402327120:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001c90 with delay 0 [16100:16100:0222/175332.466039:16402327182:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [16100:16100:0222/175332.466262:16402327407:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001e70 with delay 0 [16100:16100:0222/175332.466304:16402327461:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001c90 [16100:16100:0222/175332.466356:16402327498:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001e70 [16100:16100:0222/175332.466425:16402327570:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [16100:16100:0222/175332.466486:16402327634:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001b00 with delay 0 [16100:16100:0222/175332.466554:16402327697:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001b00 [16100:16100:0222/175332.466591:16402327734:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [16100:16100:0222/175332.466632:16402327776:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001e70 with delay 0 [16100:16100:0222/175332.466670:16402327813:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001e70 [16100:16100:0222/175332.466704:16402327848:INFO:invalidation-client-core.cc(351)] Starting with no previous state [16100:16100:0222/175332.466744:16402327894:INFO:recurring-task.cc(55)] [Startup] Scheduling 9512 with a delay 0, Now = 210919424 [16100:16100:0222/175332.466794:16402327941:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001b00 with delay 0 [16100:16100:0222/175332.466833:16402327976:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001b00 [16100:16100:0222/175332.466915:16402328064:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "8290719046960074636" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [16100:16100:0222/175332.466984:16402328128:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424 [16100:16100:0222/175332.467024:16402328168:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001e70 with delay 500 [16100:16100:0222/175332.467063:16402328212:INFO:recurring-task.cc(55)] [Retry] Scheduling 9512 with a delay 60000000, Now = 210919424 [16100:16100:0222/175332.467109:16402328258:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001e30 with delay 60000 [16100:16100:0222/175332.467164:16402328312:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001e70 [16100:16100:0222/175332.467205:16402328349:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.467256:16402328400:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.467388:16402328539: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: "8290719046960074636" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [16100:16100:0222/175332.467515:16402328664:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001e70 with delay 0 [16100:16100:0222/175332.467572:16402328719:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001e70 [16100:16100:0222/175332.467694:16402328837:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "8290719046960074636" 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" } } [16100:16100:0222/175332.467750:16402328894:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "8290719046960074636" [16100:16100:0222/175332.467791:16402328940:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [16100:16100:0222/175332.467841:16402328985:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424 [16100:16100:0222/175332.467882:16402329026:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001ee0 with delay 1200000 [16100:16100:0222/175332.467923:16402329083:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [16100:16100:0222/175332.468060:16402329212:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [16100:16100:0222/175332.468109:16402329253:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424 [16100:16100:0222/175332.468149:16402329297:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001b00 with delay 0 [16100:16100:0222/175332.468211:16402329357: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 [16100:16100:0222/175332.468261:16402329404:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001b00 [16100:16100:0222/175332.468326:16402329468:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001ef0 with delay 0 [16100:16100:0222/175332.468370:16402329514:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424 [16100:16100:0222/175332.468414:16402329558:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c90 with delay 10000 [16100:16100:0222/175332.468452:16402329595:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001ef0 [16100:16100:0222/175332.468486:16402329633:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [16100:16100:0222/175332.468553:16402329696:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.468617:16402329778:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001ef0 with delay 0 [16100:16100:0222/175332.468674:16402329820:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000001ef0 [16100:16100:0222/175332.468811:16402329962: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 } } [16100:16100:0222/175332.468901:16402330054: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 [16100:16100:0222/175332.468961:16402330112:INFO:protocol-handler.cc(294)] Adding subtree: { } [16100:16100:0222/175332.469011:16402330155:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 10376 with a delay 500000, Now = 211469424 [16100:16100:0222/175332.469051:16402330195:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001b00 with delay 500 [16100:16100:0222/175332.469093:16402330236:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [16100:16100:0222/175332.469330:16402330478: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 } [16100:16100:0222/175332.469406:16402330550:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000001b00 [16100:16100:0222/175332.469452:16402330613:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.469563:16402330707:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.469602:16402330746:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [16100:16100:0222/175332.469866:16402331012: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 } } [16100:16100:0222/175332.470204:16402331348:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000001c90 [ OK ] InvalidationClientImplTest.ServerRequests (6 ms) [15/28] InvalidationClientImplTest.ServerRequests (6 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [16100:16100:0222/175332.471809:16402332954:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000019d0 with delay 0 [16100:16100:0222/175332.471873:16402333015:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [16100:16100:0222/175332.472129:16402333274:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001e70 with delay 0 [16100:16100:0222/175332.472179:16402333329:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000019d0 [16100:16100:0222/175332.472225:16402333368:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001e70 [16100:16100:0222/175332.472305:16402333459:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [16100:16100:0222/175332.472383:16402333531:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002090 with delay 0 [16100:16100:0222/175332.472437:16402333583:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002090 [16100:16100:0222/175332.472474:16402333618:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [16100:16100:0222/175332.472515:16402333663:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001e70 with delay 0 [16100:16100:0222/175332.472572:16402333715:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001e70 [16100:16100:0222/175332.472606:16402333758:INFO:invalidation-client-core.cc(351)] Starting with no previous state [16100:16100:0222/175332.472657:16402333813:INFO:recurring-task.cc(55)] [Startup] Scheduling 9896 with a delay 0, Now = 210919424 [16100:16100:0222/175332.472709:16402333859:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002090 with delay 0 [16100:16100:0222/175332.472752:16402333895:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002090 [16100:16100:0222/175332.472821:16402333964:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "7208132189185409321" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [16100:16100:0222/175332.472864:16402334026:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9512 with a delay 500000, Now = 210919424 [16100:16100:0222/175332.472925:16402334073:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001e70 with delay 500 [16100:16100:0222/175332.472973:16402334121:INFO:recurring-task.cc(55)] [Retry] Scheduling 9896 with a delay 60000000, Now = 210919424 [16100:16100:0222/175332.473018:16402334162:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000020a0 with delay 60000 [16100:16100:0222/175332.473066:16402334218:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001e70 [16100:16100:0222/175332.473112:16402334256:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.473162:16402334317:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.473309:16402334456: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: "7208132189185409321" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [16100:16100:0222/175332.473422:16402334566:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001e70 with delay 0 [16100:16100:0222/175332.473463:16402334613:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001e70 [16100:16100:0222/175332.473819:16402334966:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "7208132189185409321" 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" } } [16100:16100:0222/175332.473909:16402335056:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "7208132189185409321" [16100:16100:0222/175332.473975:16402335126:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [16100:16100:0222/175332.474033:16402335177:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424 [16100:16100:0222/175332.474076:16402335225:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000002030 with delay 1200000 [16100:16100:0222/175332.474124:16402335272:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [16100:16100:0222/175332.474254:16402335405:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [16100:16100:0222/175332.474303:16402335452:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1032 with a delay 0, Now = 211419424 [16100:16100:0222/175332.474354:16402335503:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000002090 with delay 0 [16100:16100:0222/175332.474418:16402335568: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 [16100:16100:0222/175332.474484:16402335627:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000002090 [16100:16100:0222/175332.474563:16402335706:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000021b0 with delay 0 [16100:16100:0222/175332.474610:16402335762:INFO:recurring-task.cc(55)] [Retry] Scheduling 1032 with a delay 10000000, Now = 211419424 [16100:16100:0222/175332.474660:16402335808:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000019d0 with delay 10000 [16100:16100:0222/175332.474703:16402335846:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000021b0 [16100:16100:0222/175332.474737:16402335887:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [16100:16100:0222/175332.474801:16402335946:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.474857:16402336018:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000021b0 with delay 0 [16100:16100:0222/175332.474914:16402336068:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000021b0 [16100:16100:0222/175332.475052:16402336200: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" } } [16100:16100:0222/175332.475153:16402336298: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 [16100:16100:0222/175332.475203:16402336346:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [16100:16100:0222/175332.475525:16402336679:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7010000019d0 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (5 ms) [16/28] InvalidationClientImplTest.IncomingErrorMessage (5 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [16100:16100:0222/175332.477023:16402338169:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001e10 with delay 0 [16100:16100:0222/175332.477089:16402338232:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [16100:16100:0222/175332.477382:16402338536:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d10 with delay 0 [16100:16100:0222/175332.477441:16402338585:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001e10 [16100:16100:0222/175332.477486:16402338628:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d10 [16100:16100:0222/175332.477567:16402338711:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [16100:16100:0222/175332.477627:16402338773:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001af0 with delay 0 [16100:16100:0222/175332.477674:16402338816:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001af0 [16100:16100:0222/175332.477707:16402338851:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [16100:16100:0222/175332.477753:16402338897:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d10 with delay 0 [16100:16100:0222/175332.477793:16402338935:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d10 [16100:16100:0222/175332.477826:16402338970:INFO:invalidation-client-core.cc(351)] Starting with no previous state [16100:16100:0222/175332.477868:16402339012:INFO:recurring-task.cc(55)] [Startup] Scheduling 9608 with a delay 0, Now = 210919424 [16100:16100:0222/175332.477908:16402339052:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001af0 with delay 0 [16100:16100:0222/175332.477951:16402339094:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001af0 [16100:16100:0222/175332.478019:16402339164:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "3606933682224278452" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [16100:16100:0222/175332.478067:16402339211:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9896 with a delay 500000, Now = 210919424 [16100:16100:0222/175332.478107:16402339252:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d10 with delay 500 [16100:16100:0222/175332.478152:16402339300:INFO:recurring-task.cc(55)] [Retry] Scheduling 9608 with a delay 60000000, Now = 210919424 [16100:16100:0222/175332.478201:16402339345:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001eb0 with delay 60000 [16100:16100:0222/175332.478251:16402339395:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001d10 [16100:16100:0222/175332.478288:16402339438:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.478344:16402339488:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.478481:16402339625: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: "3606933682224278452" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [16100:16100:0222/175332.478613:16402339757:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001d10 with delay 0 [16100:16100:0222/175332.478656:16402339800:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001d10 [16100:16100:0222/175332.478779:16402339923:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "3606933682224278452" 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" } } [16100:16100:0222/175332.478836:16402339989:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "3606933682224278452" [16100:16100:0222/175332.478907:16402340055:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [16100:16100:0222/175332.478959:16402340110:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424 [16100:16100:0222/175332.479007:16402340160:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001970 with delay 1200000 [16100:16100:0222/175332.479061:16402340204:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [16100:16100:0222/175332.479195:16402340342:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [16100:16100:0222/175332.479238:16402340386:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1032 with a delay 0, Now = 211419424 [16100:16100:0222/175332.479278:16402340423:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001af0 with delay 0 [16100:16100:0222/175332.479336:16402340479: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 [16100:16100:0222/175332.479383:16402340526:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001af0 [16100:16100:0222/175332.479452:16402340595:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c30 with delay 0 [16100:16100:0222/175332.479497:16402340641:INFO:recurring-task.cc(55)] [Retry] Scheduling 1032 with a delay 10000000, Now = 211419424 [16100:16100:0222/175332.479548:16402340692:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001e10 with delay 10000 [16100:16100:0222/175332.479587:16402340729:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001c30 [16100:16100:0222/175332.479620:16402340764:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [16100:16100:0222/175332.479677:16402340823:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001c30 with delay 0 [16100:16100:0222/175332.479716:16402340861:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000001c30 [16100:16100:0222/175332.479781:16402340930:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [16100:16100:0222/175332.479850:16402341002:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9896 with a delay 500000, Now = 211469424 [16100:16100:0222/175332.479897:16402341050:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001af0 with delay 500 [16100:16100:0222/175332.479958:16402341102:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9320 with a delay 60000000, Now = 211469424 [16100:16100:0222/175332.480004:16402341153:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001c50 with delay 60000 [16100:16100:0222/175332.480067:16402341220:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000001af0 [16100:16100:0222/175332.480116:16402341260:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.480170:16402341313:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.480206:16402341353:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [16100:16100:0222/175332.480356:16402341500: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 } } } [16100:16100:0222/175332.480460:16402341604:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.480522:16402341681:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000001af0 with delay 0 [16100:16100:0222/175332.480577:16402341723:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000001af0 [16100:16100:0222/175332.480692:16402341836: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" } } [16100:16100:0222/175332.480770:16402341914: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 [16100:16100:0222/175332.480815:16402341958:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [16100:16100:0222/175332.480909:16402342053:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [16100:16100:0222/175332.481229:16402342378:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000001e10 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms) [17/28] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [16100:16100:0222/175332.482765:16402343910:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001ef0 with delay 0 [16100:16100:0222/175332.482829:16402343972:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [16100:16100:0222/175332.483075:16402344224:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000019d0 with delay 0 [16100:16100:0222/175332.483124:16402344271:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001ef0 [16100:16100:0222/175332.483165:16402344307:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000019d0 [16100:16100:0222/175332.483234:16402344378:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [16100:16100:0222/175332.483310:16402344453:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d70 with delay 0 [16100:16100:0222/175332.483359:16402344502:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d70 [16100:16100:0222/175332.483394:16402344537:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [16100:16100:0222/175332.483445:16402344589:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000019d0 with delay 0 [16100:16100:0222/175332.483488:16402344630:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000019d0 [16100:16100:0222/175332.483522:16402344666:INFO:invalidation-client-core.cc(351)] Starting with no previous state [16100:16100:0222/175332.483578:16402344724:INFO:recurring-task.cc(55)] [Startup] Scheduling 9800 with a delay 0, Now = 210919424 [16100:16100:0222/175332.483620:16402344767:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d70 with delay 0 [16100:16100:0222/175332.483660:16402344803:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d70 [16100:16100:0222/175332.483731:16402344875:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "7001296811224858754" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [16100:16100:0222/175332.483779:16402344924:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9608 with a delay 500000, Now = 210919424 [16100:16100:0222/175332.483824:16402344968:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000019d0 with delay 500 [16100:16100:0222/175332.483865:16402345015:INFO:recurring-task.cc(55)] [Retry] Scheduling 9800 with a delay 60000000, Now = 210919424 [16100:16100:0222/175332.483927:16402345077:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001ec0 with delay 60000 [16100:16100:0222/175332.483983:16402345141:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000019d0 [16100:16100:0222/175332.484037:16402345181:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.484088:16402345236:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.484226:16402345372: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: "7001296811224858754" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [16100:16100:0222/175332.484349:16402345493:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000019d0 with delay 0 [16100:16100:0222/175332.484389:16402345535:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000019d0 [16100:16100:0222/175332.484514:16402345658:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "7001296811224858754" 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" } } [16100:16100:0222/175332.484585:16402345729:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "7001296811224858754" [16100:16100:0222/175332.484630:16402345773:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [16100:16100:0222/175332.484672:16402345816:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1800 with a delay 1200000000, Now = 211419424 [16100:16100:0222/175332.484714:16402345857:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001c80 with delay 1200000 [16100:16100:0222/175332.484755:16402345899:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [16100:16100:0222/175332.484871:16402346017:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [16100:16100:0222/175332.484921:16402346076:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1032 with a delay 0, Now = 211419424 [16100:16100:0222/175332.484974:16402346118:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001d70 with delay 0 [16100:16100:0222/175332.485030:16402346182: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 [16100:16100:0222/175332.485088:16402346231:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001d70 [16100:16100:0222/175332.485155:16402346298:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001f60 with delay 0 [16100:16100:0222/175332.485200:16402346343:INFO:recurring-task.cc(55)] [Retry] Scheduling 1032 with a delay 10000000, Now = 211419424 [16100:16100:0222/175332.485239:16402346383:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001ef0 with delay 10000 [16100:16100:0222/175332.485275:16402346418:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001f60 [16100:16100:0222/175332.485308:16402346454:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [16100:16100:0222/175332.485365:16402346509:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001f60 with delay 0 [16100:16100:0222/175332.485408:16402346553:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000001f60 [16100:16100:0222/175332.485465:16402346609:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [16100:16100:0222/175332.485524:16402346678:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 9608 with a delay 500000, Now = 211469424 [16100:16100:0222/175332.485572:16402346718:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001d70 with delay 500 [16100:16100:0222/175332.485613:16402346757:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 9416 with a delay 60000000, Now = 211469424 [16100:16100:0222/175332.485652:16402346797:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000002060 with delay 60000 [16100:16100:0222/175332.485708:16402346851:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000001d70 [16100:16100:0222/175332.485748:16402346892:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.485797:16402346943:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.485837:16402346984:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [16100:16100:0222/175332.485979:16402347125: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 } } } [16100:16100:0222/175332.486284:16402347429:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000001ef0 [16100:16100:0222/175332.487483:16402348626:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000001ec0 [16100:16100:0222/175332.487533:16402348683:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x701000002060 [16100:16100:0222/175332.487599:16402348755: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 [16100:16100:0222/175332.487658:16402348802:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [16100:16100:0222/175332.487759:16402348910: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 } [16100:16100:0222/175332.487810:16402348955:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9608 with a delay 500000, Now = 271469424 [16100:16100:0222/175332.487850:16402348994:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000001ec0 with delay 500 [16100:16100:0222/175332.487890:16402349034:INFO:recurring-task.cc(55)] [Retry] Scheduling 9416 with a delay 60000000, Now = 271469424 [16100:16100:0222/175332.487934:16402349079:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000001ef0 with delay 60000 [16100:16100:0222/175332.487986:16402349130:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x701000001ec0 [16100:16100:0222/175332.488023:16402349175:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.488089:16402349233:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.488129:16402349272:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [16100:16100:0222/175332.488279:16402349423: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) [18/28] InvalidationClientImplTest.NetworkTimeouts (7 ms) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary [16100:16100:0222/175332.490070:16402351215:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d60 with delay 0 [16100:16100:0222/175332.490134:16402351276:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [16100:16100:0222/175332.490339:16402351498:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001f20 with delay 0 [16100:16100:0222/175332.490397:16402351541:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d60 [16100:16100:0222/175332.490439:16402351581:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001f20 [16100:16100:0222/175332.490508:16402351652:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [16100:16100:0222/175332.490583:16402351727:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002060 with delay 0 [16100:16100:0222/175332.490630:16402351773:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002060 [16100:16100:0222/175332.490665:16402351814:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [16100:16100:0222/175332.490712:16402351856:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001f20 with delay 0 [16100:16100:0222/175332.490749:16402351892:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001f20 [16100:16100:0222/175332.490786:16402351930:INFO:invalidation-client-core.cc(351)] Starting with no previous state [16100:16100:0222/175332.490826:16402351976:INFO:recurring-task.cc(55)] [Startup] Scheduling 10376 with a delay 0, Now = 210919424 [16100:16100:0222/175332.490890:16402352034:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002060 with delay 0 [16100:16100:0222/175332.490942:16402352085:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002060 [16100:16100:0222/175332.491012:16402352156:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "6991087154045782667" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [16100:16100:0222/175332.491056:16402352200:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 9992 with a delay 500000, Now = 210919424 [16100:16100:0222/175332.491094:16402352239:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001f20 with delay 500 [16100:16100:0222/175332.491130:16402352278:INFO:recurring-task.cc(55)] [Retry] Scheduling 10376 with a delay 60000000, Now = 210919424 [16100:16100:0222/175332.491170:16402352316:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d90 with delay 60000 [16100:16100:0222/175332.491220:16402352364:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001f20 [16100:16100:0222/175332.491259:16402352402:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.491311:16402352457:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.491443:16402352587: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: "6991087154045782667" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [16100:16100:0222/175332.491564:16402352713:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001f20 with delay 0 [16100:16100:0222/175332.491610:16402352756:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001f20 [16100:16100:0222/175332.491732:16402352883:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "6991087154045782667" 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" } } [16100:16100:0222/175332.491796:16402352940:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "6991087154045782667" [16100:16100:0222/175332.491837:16402352986:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [16100:16100:0222/175332.491888:16402353032:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1464 with a delay 1200000000, Now = 211419424 [16100:16100:0222/175332.491927:16402353077:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001d70 with delay 1200000 [16100:16100:0222/175332.491977:16402353121:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [16100:16100:0222/175332.492091:16402353235:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [16100:16100:0222/175332.492131:16402353275:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1032 with a delay 0, Now = 211419424 [16100:16100:0222/175332.492171:16402353315:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000002060 with delay 0 [16100:16100:0222/175332.492226:16402353372: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 [16100:16100:0222/175332.492284:16402353427:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000002060 [16100:16100:0222/175332.492356:16402353499:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001f60 with delay 0 [16100:16100:0222/175332.492400:16402353544:INFO:recurring-task.cc(55)] [Retry] Scheduling 1032 with a delay 10000000, Now = 211419424 [16100:16100:0222/175332.492440:16402353584:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001d60 with delay 10000 [16100:16100:0222/175332.492477:16402353619:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001f60 [16100:16100:0222/175332.492509:16402353654:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [16100:16100:0222/175332.492577:16402353721:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.492626:16402353771:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000001f60 with delay 0 [16100:16100:0222/175332.492666:16402353811:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000001f60 [16100:16100:0222/175332.492761:16402353905: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" } } [16100:16100:0222/175332.493045:16402354189:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000001d60 [16100:16100:0222/175332.494054:16402355204:INFO:invalidation-client-impl_test.cc(477)] Reg manager state: { client_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_summary: { num_registrations: 1 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } } [ OK ] InvalidationClientImplTest.NoRegistrationSummary (5 ms) [19/28] InvalidationClientImplTest.NoRegistrationSummary (5 ms) [ RUN ] InvalidationClientImplTest.Heartbeats [16100:16100:0222/175332.494617:16402355761:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000001d80 with delay 0 [16100:16100:0222/175332.494678:16402355821:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [16100:16100:0222/175332.494899:16402356043:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002020 with delay 0 [16100:16100:0222/175332.494951:16402356095:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000001d80 [16100:16100:0222/175332.494990:16402356133:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002020 [16100:16100:0222/175332.495056:16402356200:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [16100:16100:0222/175332.495124:16402356268:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002060 with delay 0 [16100:16100:0222/175332.495169:16402356312:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002060 [16100:16100:0222/175332.495203:16402356350:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [16100:16100:0222/175332.495244:16402356391:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002020 with delay 0 [16100:16100:0222/175332.495283:16402356426:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002020 [16100:16100:0222/175332.495316:16402356460:INFO:invalidation-client-core.cc(351)] Starting with no previous state [16100:16100:0222/175332.495358:16402356501:INFO:recurring-task.cc(55)] [Startup] Scheduling 9704 with a delay 0, Now = 210919424 [16100:16100:0222/175332.495396:16402356548:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002060 with delay 0 [16100:16100:0222/175332.495450:16402356592:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000002060 [16100:16100:0222/175332.495518:16402356662:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-6243314667615213155" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [16100:16100:0222/175332.495572:16402356721:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 10376 with a delay 500000, Now = 210919424 [16100:16100:0222/175332.495614:16402356765:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000002020 with delay 500 [16100:16100:0222/175332.495659:16402356803:INFO:recurring-task.cc(55)] [Retry] Scheduling 9704 with a delay 60000000, Now = 210919424 [16100:16100:0222/175332.495704:16402356848:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000020d0 with delay 60000 [16100:16100:0222/175332.495755:16402356899:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000002020 [16100:16100:0222/175332.495793:16402356937:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.495841:16402356990:INFO:invalidation-client-core.cc(488)] Return client token = "" [16100:16100:0222/175332.496000:16402357145: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: "-6243314667615213155" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [16100:16100:0222/175332.496115:16402357259:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000002020 with delay 0 [16100:16100:0222/175332.496161:16402357305:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000002020 [16100:16100:0222/175332.496281:16402357425:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-6243314667615213155" 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" } } [16100:16100:0222/175332.496342:16402357486:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-6243314667615213155" [16100:16100:0222/175332.496384:16402357528:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [16100:16100:0222/175332.496435:16402357579:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1464 with a delay 1200000000, Now = 211419424 [16100:16100:0222/175332.496479:16402357628:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001f60 with delay 1200000 [16100:16100:0222/175332.496528:16402357681:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [16100:16100:0222/175332.496654:16402357798:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [16100:16100:0222/175332.496695:16402357838:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1032 with a delay 0, Now = 211419424 [16100:16100:0222/175332.496733:16402357877:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000002060 with delay 0 [16100:16100:0222/175332.496788:16402357931: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 [16100:16100:0222/175332.496835:16402357977:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000002060 [16100:16100:0222/175332.496901:16402358044:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001f20 with delay 0 [16100:16100:0222/175332.496949:16402358100:INFO:recurring-task.cc(55)] [Retry] Scheduling 1032 with a delay 10000000, Now = 211419424 [16100:16100:0222/175332.497002:16402358151:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000001d80 with delay 10000 [16100:16100:0222/175332.497051:16402358193:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000001f20 [16100:16100:0222/175332.497089:16402358233:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [16100:16100:0222/175332.497382:16402358530:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000001d80 [16100:16100:0222/175332.498563:16402359706:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7010000020d0 [16100:16100:0222/175332.524793:16402385939:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x701000001f60 [16100:16100:0222/175332.524881:16402386025:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [16100:16100:0222/175332.524953:16402386097:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [16100:16100:0222/175332.524996:16402386141:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [16100:16100:0222/175332.525192:16402386338: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 } [16100:16100:0222/175332.525246:16402386390:INFO:recurring-task.cc(55)] [Send-info] Scheduling 10376 with a delay 500000, Now = 1411419424 [16100:16100:0222/175332.525287:16402386432:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7010000020d0 with delay 500 [16100:16100:0222/175332.525331:16402386475:INFO:recurring-task.cc(55)] [Retry] Scheduling 1464 with a delay 1200000000, Now = 1411419424 [16100:16100:0222/175332.525370:16402386515:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000001d80 with delay 1200000 [16100:16100:0222/175332.525421:16402386566:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x7010000020d0 [16100:16100:0222/175332.525460:16402386603:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.525533:16402386691:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [16100:16100:0222/175332.525594:16402386739:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [16100:16100:0222/175332.525831:16402386975:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 778801000 max_known_server_time_ms: 314159265 message_id: "2" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "InvClientTest" } performance_counter: { name: "SentMessageType.INITIALIZE" value: 1 } performance_counter: { name: "SentMessageType.TOTAL" value: 1 } performance_counter: { name: "ReceivedMessageType.TOKEN_CONTROL" value: 1 } performance_counter: { name: "ReceivedMessageType.TOTAL" value: 1 } performance_counter: { name: "ListenerEventType.REISSUE_REGISTRATIONS" value: 1 } performance_counter: { name: "ClientErrorType.PERSISTENT_READ_FAILURE" value: 1 } server_registration_summary_requested: false } } [ OK ] InvalidationClientImplTest.Heartbeats (33 ms) [20/28] InvalidationClientImplTest.Heartbeats (33 ms) [ RUN ] ProtocolHandlerTest.TokenMissing [16102:16102:0222/175332.538009:16402399160:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000012a0 with delay 0 [16102:16102:0222/175332.538115:16402399262:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000012a0 [16102:16102:0222/175332.538482:16402399632: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 } [16102:16102:0222/175332.538562:16402399707:INFO:recurring-task.cc(55)] [Send-info] Scheduling 9224 with a delay 500000, Now = 210919424 [16102:16102:0222/175332.538606:16402399750:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000012b0 with delay 500 [16102:16102:0222/175332.538658:16402399803:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000012b0 [16102:16102:0222/175332.538768:16402399912:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [16102:16102:0222/175332.538815:16402399959:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (2 ms) [21/28] ProtocolHandlerTest.TokenMissing (2 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [16102:16102:0222/175332.539359:16402400504:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000012b0 with delay 0 [16102:16102:0222/175332.539403:16402400550:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000012b0 [16102:16102:0222/175332.539456:16402400600:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 9320 with a delay 500000, Now = 210919424 [16102:16102:0222/175332.539504:16402400648:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000012a0 with delay 500 [16102:16102:0222/175332.539564:16402400708:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000012a0 [16102:16102:0222/175332.539677:16402400823:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [16102:16102:0222/175332.539755:16402400899: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 } [16102:16102:0222/175332.539822:16402400968: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 } } [16102:16102:0222/175332.539965:16402401114: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 } } } [16102:16102:0222/175332.540110:16402401255:ERROR:protocol-handler.cc(323)] Tried to send invalid message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true is_trickle_restart: true } } } [ OK ] ProtocolHandlerTest.InvalidOutboundMessage (1 ms) [22/28] ProtocolHandlerTest.InvalidOutboundMessage (1 ms) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage [16102:16102:0222/175332.540633:16402401778:INFO:protocol-handler.cc(139)] Incoming message: { } [16102:16102:0222/175332.540684:16402401831:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [16102:16102:0222/175332.540725:16402401869:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [23/28] ProtocolHandlerTest.UnparseableInboundMessage (0 ms) [ RUN ] RecurringTaskTest.PeriodicTask [16102:16102:0222/175332.540998:16402402142:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -1042824360 with a delay 10000, Now = 0 [16102:16102:0222/175332.541041:16402402184:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000001110 with delay 10 [16102:16102:0222/175332.541090:16402402234:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000001110 [16102:16102:0222/175332.541127:16402402273:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [16102:16102:0222/175332.541165:16402402309:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824360 with a delay 60000, Now = 10000 [16102:16102:0222/175332.541204:16402402347:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000001120 with delay 60 [16102:16102:0222/175332.541247:16402402389:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x701000001120 [16102:16102:0222/175332.541278:16402402420:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [16102:16102:0222/175332.541309:16402402451:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824360 with a delay 60000, Now = 70000 [16102:16102:0222/175332.541340:16402402482:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x701000001110 with delay 60 [16102:16102:0222/175332.541373:16402402515:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x701000001110 [16102:16102:0222/175332.541404:16402402546:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [16102:16102:0222/175332.541435:16402402577:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824360 with a delay 60000, Now = 130000 [16102:16102:0222/175332.541466:16402402608:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x701000001120 with delay 60 [16102:16102:0222/175332.541506:16402402648:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x701000001120 [16102:16102:0222/175332.541546:16402402688:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [16102:16102:0222/175332.541578:16402402720:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824360 with a delay 60000, Now = 190000 [16102:16102:0222/175332.541609:16402402751:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x701000001110 with delay 60 [16102:16102:0222/175332.541642:16402402784:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x701000001110 [16102:16102:0222/175332.541673:16402402815:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [16102:16102:0222/175332.541704:16402402846:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824360 with a delay 60000, Now = 250000 [16102:16102:0222/175332.541735:16402402877:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x701000001120 with delay 60 [16102:16102:0222/175332.541768:16402402910:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x701000001120 [16102:16102:0222/175332.541798:16402402940:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [16102:16102:0222/175332.541829:16402402971:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824360 with a delay 60000, Now = 310000 [16102:16102:0222/175332.541860:16402403002:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x701000001110 with delay 60 [16102:16102:0222/175332.541892:16402403034:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x701000001110 [16102:16102:0222/175332.541927:16402403069:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [16102:16102:0222/175332.541958:16402403100:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824360 with a delay 60000, Now = 370000 [16102:16102:0222/175332.541991:16402403133:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x701000001120 with delay 60 [16102:16102:0222/175332.542025:16402403168:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x701000001120 [16102:16102:0222/175332.542061:16402403205:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (3 ms) [24/28] RecurringTaskTest.PeriodicTask (3 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [16102:16102:0222/175332.543434:16402404579:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -1042824544 with a delay 10000, Now = 0 [16102:16102:0222/175332.543476:16402404626:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000001120 with delay 10 [16102:16102:0222/175332.543520:16402404666:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000001120 [16102:16102:0222/175332.543570:16402404714:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [16102:16102:0222/175332.543607:16402404751:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824544 with a delay 50000, Now = 10000 [16102:16102:0222/175332.543646:16402404790:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000001110 with delay 50 [16102:16102:0222/175332.543691:16402404838:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x701000001110 [16102:16102:0222/175332.543729:16402404885:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [16102:16102:0222/175332.543779:16402404929:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824544 with a delay 149000, Now = 60000 [16102:16102:0222/175332.543825:16402404969:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x701000001120 with delay 149 [16102:16102:0222/175332.543870:16402405014:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x701000001120 [16102:16102:0222/175332.543911:16402405059:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [16102:16102:0222/175332.543956:16402405102:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824544 with a delay 248000, Now = 210000 [16102:16102:0222/175332.543999:16402405147:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x701000001110 with delay 248 [16102:16102:0222/175332.544046:16402405190:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x701000001110 [16102:16102:0222/175332.544083:16402405232:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [16102:16102:0222/175332.544127:16402405270:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824544 with a delay 446000, Now = 460000 [16102:16102:0222/175332.544164:16402405307:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x701000001120 with delay 446 [16102:16102:0222/175332.544213:16402405356:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x701000001120 [16102:16102:0222/175332.544247:16402405390:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [16102:16102:0222/175332.544284:16402405427:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824544 with a delay 842000, Now = 910000 [16102:16102:0222/175332.544321:16402405464:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x701000001110 with delay 842 [16102:16102:0222/175332.544379:16402405521:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x701000001110 [16102:16102:0222/175332.544410:16402405552:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [16102:16102:0222/175332.544441:16402405583:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824544 with a delay 1040000, Now = 1760000 [16102:16102:0222/175332.544472:16402405621:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x701000001120 with delay 1040 [16102:16102:0222/175332.544548:16402405690:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x701000001120 [16102:16102:0222/175332.544584:16402405726:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [16102:16102:0222/175332.544615:16402405757:INFO:recurring-task.cc(55)] [Retry] Scheduling -1042824544 with a delay 1040000, Now = 2800000 [16102:16102:0222/175332.544646:16402405788:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x701000001110 with delay 1040 [16102:16102:0222/175332.544702:16402405844:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x701000001110 [16102:16102:0222/175332.544732:16402405874:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (2 ms) [25/28] RecurringTaskTest.ExponentialBackoffTask (2 ms) [ RUN ] RecurringTaskTest.OneShotTask [16102:16102:0222/175332.545926:16402407071:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -1042824504 with a delay 10000, Now = 0 [16102:16102:0222/175332.545975:16402407122:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000001110 with delay 10 [16102:16102:0222/175332.546019:16402407163:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000001110 [16102:16102:0222/175332.546054:16402407200:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [16102:16102:0222/175332.546097:16402407247:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -1042824504 with a delay 10000, Now = 10000 [16102:16102:0222/175332.546140:16402407288:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000001110 with delay 10 [16102:16102:0222/175332.546184:16402407328:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x701000001110 [16102:16102:0222/175332.546221:16402407364:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (2 ms) [26/28] RecurringTaskTest.OneShotTask (2 ms) [ RUN ] ThrottleTest.ThrottlingScripted [16102:16102:0222/175332.547546:16402408693:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x701000001110 with delay 920 [16102:16102:0222/175332.547613:16402408756:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x701000001110 [16102:16102:0222/175332.547970:16402409114:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x701000001110 with delay 45000 [16102:16102:0222/175332.549028:16402410171:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x701000001110 [ OK ] ThrottleTest.ThrottlingScripted (2 ms) [27/28] ThrottleTest.ThrottlingScripted (2 ms) [ RUN ] ThrottleTest.ThrottlingStorm [16102:16102:0222/175332.549162:16402410308:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000001110 with delay 990 [16102:16102:0222/175332.549229:16402410372:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x701000001110 [16102:16102:0222/175332.549268:16402410410:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.549328:16402410470:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x701000001110 [16102:16102:0222/175332.549360:16402410502:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.549420:16402410562:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x701000001110 [16102:16102:0222/175332.549452:16402410594:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.549517:16402410658:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x701000001110 [16102:16102:0222/175332.549556:16402410698:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.549616:16402410757:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x701000001110 [16102:16102:0222/175332.549647:16402410789:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.549706:16402410848:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x701000001110 [16102:16102:0222/175332.549739:16402410888:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x701000001120 with delay 54000 [16102:16102:0222/175332.551404:16402412547:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x701000001120 [16102:16102:0222/175332.551442:16402412583:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x701000001120 with delay 1000 [16102:16102:0222/175332.551505:16402412647:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x701000001120 [16102:16102:0222/175332.551545:16402412686:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x701000001120 with delay 1000 [16102:16102:0222/175332.551605:16402412746:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x701000001120 [16102:16102:0222/175332.551637:16402412778:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x701000001120 with delay 1000 [16102:16102:0222/175332.551696:16402412837:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x701000001120 [16102:16102:0222/175332.551727:16402412868:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x701000001120 with delay 1000 [16102:16102:0222/175332.551786:16402412927:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x701000001120 [16102:16102:0222/175332.551817:16402412959:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x701000001120 with delay 1000 [16102:16102:0222/175332.551879:16402413021:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x701000001120 [16102:16102:0222/175332.551911:16402413052:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x701000001120 with delay 1000 [16102:16102:0222/175332.551969:16402413111:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x701000001120 [16102:16102:0222/175332.552003:16402413145:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x701000001110 with delay 54000 [16102:16102:0222/175332.553686:16402414829:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x701000001110 [16102:16102:0222/175332.553723:16402414865:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.553783:16402414925:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x701000001110 [16102:16102:0222/175332.553815:16402414956:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.553874:16402415016:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x701000001110 [16102:16102:0222/175332.553906:16402415048:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.553965:16402415107:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x701000001110 [16102:16102:0222/175332.553999:16402415140:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.554058:16402415200:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x701000001110 [16102:16102:0222/175332.554090:16402415232:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.554149:16402415291:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x701000001110 [16102:16102:0222/175332.554181:16402415322:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.554239:16402415381:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x701000001110 [16102:16102:0222/175332.554271:16402415413:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x701000001120 with delay 54000 [16102:16102:0222/175332.556001:16402417144:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x701000001120 [16102:16102:0222/175332.556038:16402417180:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x701000001120 with delay 1000 [16102:16102:0222/175332.556098:16402417240:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x701000001120 [16102:16102:0222/175332.556135:16402417276:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x701000001120 with delay 1000 [16102:16102:0222/175332.556194:16402417335:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x701000001120 [16102:16102:0222/175332.556225:16402417367:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x701000001120 with delay 1000 [16102:16102:0222/175332.556285:16402417426:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x701000001120 [16102:16102:0222/175332.556316:16402417458:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x701000001120 with delay 1000 [16102:16102:0222/175332.556375:16402417516:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x701000001120 [16102:16102:0222/175332.556406:16402417547:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x701000001120 with delay 1000 [16102:16102:0222/175332.556467:16402417608:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x701000001120 [16102:16102:0222/175332.556504:16402417645:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x701000001120 with delay 1000 [16102:16102:0222/175332.556570:16402417712:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x701000001120 [16102:16102:0222/175332.556607:16402417749:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x701000001110 with delay 54000 [16102:16102:0222/175332.558299:16402419442:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x701000001110 [16102:16102:0222/175332.558337:16402419479:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.558397:16402419539:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x701000001110 [16102:16102:0222/175332.558429:16402419571:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.558494:16402419636:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x701000001110 [16102:16102:0222/175332.558526:16402419675:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.558593:16402419735:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x701000001110 [16102:16102:0222/175332.558625:16402419767:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.558685:16402419826:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x701000001110 [16102:16102:0222/175332.558716:16402419858:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.558775:16402419917:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x701000001110 [16102:16102:0222/175332.558806:16402419948:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x701000001110 with delay 1000 [16102:16102:0222/175332.558866:16402420017:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x701000001110 [16102:16102:0222/175332.558908:16402420050:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x701000001120 with delay 54000 [16102:16102:0222/175332.560640:16402421782:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x701000001120 [ OK ] ThrottleTest.ThrottlingStorm (11 ms) [28/28] ThrottleTest.ThrottlingStorm (11 ms) SUCCESS: all tests passed. Tests took 0 seconds. 2019-02-23 20:00:12,589 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmpQNM1TS/433676236eaca410'] 2019-02-23 20:00:12,589 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmpQNM1TS/433676236eaca410/output.json'] 2019-02-23 20:00:12,590 - root: [INFO] merge_cmd: /b/swarming/w/ir/cache/vpython/ba947a/bin/python /b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/swarming/resources/standard_gtest_merge.py --build-properties {"bot_id": "swarm2372-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "user:luci-scheduler@appspot.gserviceaccount.com", "created_ts": 1550980359589551, "id": "8920672934421803088", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux MSan Tests/15179", "builder:Linux MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "gitiles_ref:refs/heads/master", "parent_buildername:Linux MSan Builder", "parent_buildnumber:17448", "scheduler_invocation_id:9086102996586304176", "scheduler_job_id:chromium/Linux MSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux MSan Tests", "buildnumber": 15179, "got_angle_revision": "f78131dac0763e4c2d1310a9560cbd311e5dea64", "got_dawn_revision": "87bf834109fd5d372e62901101f285d4fb65fe67", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "got_revision_cp": "refs/heads/master@{#634985}", "got_swarming_client_revision": "d50a88f50782ba29076061b94c7b9d08a6c7e424", "got_v8_revision": "2f408608876b015b5c40977a6e3bf3984ce8cbe8", "got_v8_revision_cp": "refs/heads/7.4.207@{#1}", "got_webrtc_revision": "8721bb30d86d400a81c9b994e0e1a34a45e7e77b", "got_webrtc_revision_cp": "refs/heads/master@{#26825}", "mastername": "chromium.memory", "parent_buildername": "Linux MSan Builder", "parent_got_angle_revision": "f78131dac0763e4c2d1310a9560cbd311e5dea64", "parent_got_dawn_revision": "87bf834109fd5d372e62901101f285d4fb65fe67", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "parent_got_revision_cp": "refs/heads/master@{#634985}", "parent_got_swarming_client_revision": "d50a88f50782ba29076061b94c7b9d08a6c7e424", "parent_got_v8_revision": "2f408608876b015b5c40977a6e3bf3984ce8cbe8", "parent_got_v8_revision_cp": "refs/heads/7.4.207@{#1}", "parent_got_webrtc_revision": "8721bb30d86d400a81c9b994e0e1a34a45e7e77b", "parent_got_webrtc_revision_cp": "refs/heads/master@{#26825}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "swarm_hashes": {"accessibility_unittests": "90bbd359d293244647b6945aed752269a1c74543", "angle_unittests": "40a95d65697fc6014cefd698641bf85a74ff3364", "app_shell_unittests": "a35f35c1f5c1714e8037b479390f97d5dd5c8ddf", "aura_unittests": "db6a27a0ae59005c1f435497342bddd5aff7e511", "base_unittests": "548103e04b38b08c3fb3e2562a301d9e71023ccb", "blink_common_unittests": "b05926a8311e85c1600d44b0d382cdf3228e4264", "blink_fuzzer_unittests": "65a11bdf6e2d09db13bde094583e996425422174", "blink_heap_unittests": "a635ba0044fee7c8059076fc21631dd9b2e93cb1", "blink_platform_unittests": "fd6cdcec71de25b73efb700201c2ea3355266bbd", "blink_unittests": "1bc89b758cd719b8c8382345159bb63a85aab134", "boringssl_crypto_tests": "46efeae8d7d0ab5da926529e0312c4f4b53bd753", "boringssl_ssl_tests": "0e94168488e5a6fbaa902424cf945008172a8d9f", "browser_tests": "5b4f162529c163e86039d5928b7a29247cfafcd4", "cacheinvalidation_unittests": "770199c099aa65fd3b11986ba5f9e537f73abb6f", "capture_unittests": "c847615a4f08d250db7a8083701e930f0bd93368", "cast_unittests": "52d2b130879283bb1cf51025f21bb016ac860ea6", "cc_unittests": "69c1c96f053dd9ac740814249eaa3052fce19b6f", "chrome_app_unittests": "bd6708ff6775a787a94b1804495b3964beba6600", "chromedriver_unittests": "85e07b07ae5fdabd694c905b8927cf257cdb5f3f", "components_browsertests": "492a00938dcae8cb412cd7febfe790c9caf91ef6", "components_unittests": "af47f66ba16432484d8803776be6902736938b70", "compositor_unittests": "fc75840984122747a3542e4914eca0909a2e7cf1", "content_browsertests": "0ce43d7dfd6182b74887564f25e6dc291f21e347", "content_unittests": "83094c2109a4389c8b8d3d6a8d5886a0763a1062", "cronet_tests": "70f62a590fa2723349e507654e4dd67814686c76", "cronet_unittests": "9a976839c420c9b1c0967743d6a4f0140ffcfd3c", "crypto_unittests": "2ae959e43142f1a7165561bca532dcdfe52dfe96", "dbus_unittests": "28453e90b321a2c5afacb6e91e9ad83099e53c15", "device_unittests": "8bddd84790afbdfbec2acb24fe3ea4530e388058", "display_unittests": "f9ef06e042d6997f75ec019f812d4d3d29ad80c9", "events_unittests": "edefa705b88e4e6c7ae4128dce4e4f4a4f494e8d", "extensions_browsertests": "41d1e03a1ff711ba793e3ea2b163d47ee7c61b09", "extensions_unittests": "9b422727ae90514586ab6ca7a0618b6d53d1700f", "filesystem_service_unittests": "0cb638ea21f3cb25c6619b89a10f25abc5441fd8", "gcm_unit_tests": "e0f48c4ba3f4ba13edff836ac8735bd6a8a7d48c", "gfx_unittests": "926ab7ec3040d30cec5d8f0d83ff86a784bf5d0a", "gin_unittests": "51fd7923436d5f507bf717a1ea3e10a425709609", "gl_unittests": "4430054f1e06739b53a46cbd4ab9808d0bed26c2", "google_apis_unittests": "78d0ee01512abbc63dfdd16065684f10f1890a87", "gpu_unittests": "2e77f6c4c448bfc31708c8ff4523e59d3eee8ac9", "headless_browsertests": "24472f0157389af7b7d911ca4021609d6c6e2bf1", "headless_unittests": "d03a9b5c4a42ea34d6a894037ffad5e9e095569a", "interactive_ui_tests": "ae27269f6e5ffb394f181ff377807cd4e58db37c", "ipc_tests": "ec90b18191c09014aabf6f2226c071a8962d1c15", "jingle_unittests": "4c322fae7aceb37a2101a8cad4300758e550fb6a", "latency_unittests": "2868adeb258e67d3a76bccd283b91d2c686a3599", "leveldb_service_unittests": "0e8a9c7c1dfd57d06aadf5c9de6038f8d4c9352f", "libjingle_xmpp_unittests": "8ef6e50e2e4dc333ca8884dc54232e2b0e9e9069", "media_blink_unittests": "a2aa9a5e767b5a9ffb0e126e7c335be59f1bd911", "media_service_unittests": "0f6498294bc41993507f50d3fe9c9ec6a110b4ee", "media_unittests": "8dad22d953f1071e5abd8b7f2a1517c64772d6da", "message_center_unittests": "d4b5e24c980e4a323885726dedddd3d1db893482", "midi_unittests": "6e18d97ba4890fb1f01921973296660dbc761de1", "mojo_core_unittests": "f1673b79b29f075a2793dc31cac29e71b5acb6dd", "mojo_unittests": "c0e19e8e7847fb65a60ea511a5968940684b0b36", "nacl_helper_nonsfi_unittests": "0d861f9fb2d6adde53388df86a65de07890d79c2", "nacl_loader_unittests": "19edec03d0a53ce71e8c7ea36d33c15965ea05ec", "native_theme_unittests": "6d10d1913a21926d6a1d96d8f85192b0087344be", "net_unittests": "d1f8234a14d5041d68583d6c4ea852faebf204ca", "pdf_unittests": "ce5d5679da7c3bf2c192732cbbdcfb2e86b4ef78", "ppapi_unittests": "b7e5da945d1aacd78716d275e207319a83dc36f2", "printing_unittests": "350bb5a373c5b5995a9f463d4c90db0286e4bbfc", "remoting_unittests": "30616f86fe250e7d79f9bfd5ca95550fe1b08e67", "sandbox_linux_unittests": "9ffb7c0b2a7c34773bbb23f21c52aac043eec64c", "service_manager_unittests": "023c2640bea2c2ff3283835394f7843611504aa6", "shell_dialogs_unittests": "c85719364c336ef6ed7b293ca26cb70837abcee7", "skia_unittests": "cfab406a21f83b631e82c16253e4aaa53cf4399f", "snapshot_unittests": "36790e36faffd70ed77c55fcabfd53a5bdde6fb5", "sql_unittests": "661da5b767d67d0a141f831b039616086156a96b", "storage_unittests": "efc190c569da8be94b7e75e4c16412773b9c140b", "sync_integration_tests": "a4b0da9a3c2bc600d11745305df76369eaa58252", "traffic_annotation_auditor_unittests": "f4384285fa084a3b5aeb6ef8c90e1222fd04bb05", "ui_base_unittests": "5f6e27bd982e78a3e558ff54fc9459dadd3e19c0", "ui_touch_selection_unittests": "088212858d2f07004fe6cf7f94be87b5869ad445", "unit_tests": "aa7cb15a5661973275e07892cc9648ad14b48bad", "url_unittests": "bbdfe2050b11961ac9fc990d279d4f19d79c26ac", "views_unittests": "c01deaf6915d5f120488973d178943cb81d40754", "viz_unittests": "8b72b198b734b027f409f816e16845a799162577", "vr_common_unittests": "e0ba97988008c3937e3c14187ed1c962e3678e33", "vr_pixeltests": "2c5a05b7fd40750721fac1ae20b28e27b003cb00", "wm_unittests": "dcb155506fd5ca35fb6fb67bc28f2736e568b937", "wtf_unittests": "0e0c40459abb4d40e8f57601218ea3e438ff884c"}} --summary-json /b/swarming/w/ir/tmp/t/tmptIWyRX.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpQNM1TS -o /b/swarming/w/ir/tmp/t/tmpRT7R4H.json /b/swarming/w/ir/tmp/t/tmpQNM1TS/433676236eaca410/output.json Running ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/swarming/resources/standard_gtest_merge.py', '--build-properties', '{"bot_id": "swarm2372-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "user:luci-scheduler@appspot.gserviceaccount.com", "created_ts": 1550980359589551, "id": "8920672934421803088", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux MSan Tests/15179", "builder:Linux MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "gitiles_ref:refs/heads/master", "parent_buildername:Linux MSan Builder", "parent_buildnumber:17448", "scheduler_invocation_id:9086102996586304176", "scheduler_job_id:chromium/Linux MSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux MSan Tests", "buildnumber": 15179, "got_angle_revision": "f78131dac0763e4c2d1310a9560cbd311e5dea64", "got_dawn_revision": "87bf834109fd5d372e62901101f285d4fb65fe67", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "got_revision_cp": "refs/heads/master@{#634985}", "got_swarming_client_revision": "d50a88f50782ba29076061b94c7b9d08a6c7e424", "got_v8_revision": "2f408608876b015b5c40977a6e3bf3984ce8cbe8", "got_v8_revision_cp": "refs/heads/7.4.207@{#1}", "got_webrtc_revision": "8721bb30d86d400a81c9b994e0e1a34a45e7e77b", "got_webrtc_revision_cp": "refs/heads/master@{#26825}", "mastername": "chromium.memory", "parent_buildername": "Linux MSan Builder", "parent_got_angle_revision": "f78131dac0763e4c2d1310a9560cbd311e5dea64", "parent_got_dawn_revision": "87bf834109fd5d372e62901101f285d4fb65fe67", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "parent_got_revision_cp": "refs/heads/master@{#634985}", "parent_got_swarming_client_revision": "d50a88f50782ba29076061b94c7b9d08a6c7e424", "parent_got_v8_revision": "2f408608876b015b5c40977a6e3bf3984ce8cbe8", "parent_got_v8_revision_cp": "refs/heads/7.4.207@{#1}", "parent_got_webrtc_revision": "8721bb30d86d400a81c9b994e0e1a34a45e7e77b", "parent_got_webrtc_revision_cp": "refs/heads/master@{#26825}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "swarm_hashes": {"accessibility_unittests": "90bbd359d293244647b6945aed752269a1c74543", "angle_unittests": "40a95d65697fc6014cefd698641bf85a74ff3364", "app_shell_unittests": "a35f35c1f5c1714e8037b479390f97d5dd5c8ddf", "aura_unittests": "db6a27a0ae59005c1f435497342bddd5aff7e511", "base_unittests": "548103e04b38b08c3fb3e2562a301d9e71023ccb", "blink_common_unittests": "b05926a8311e85c1600d44b0d382cdf3228e4264", "blink_fuzzer_unittests": "65a11bdf6e2d09db13bde094583e996425422174", "blink_heap_unittests": "a635ba0044fee7c8059076fc21631dd9b2e93cb1", "blink_platform_unittests": "fd6cdcec71de25b73efb700201c2ea3355266bbd", "blink_unittests": "1bc89b758cd719b8c8382345159bb63a85aab134", "boringssl_crypto_tests": "46efeae8d7d0ab5da926529e0312c4f4b53bd753", "boringssl_ssl_tests": "0e94168488e5a6fbaa902424cf945008172a8d9f", "browser_tests": "5b4f162529c163e86039d5928b7a29247cfafcd4", "cacheinvalidation_unittests": "770199c099aa65fd3b11986ba5f9e537f73abb6f", "capture_unittests": "c847615a4f08d250db7a8083701e930f0bd93368", "cast_unittests": "52d2b130879283bb1cf51025f21bb016ac860ea6", "cc_unittests": "69c1c96f053dd9ac740814249eaa3052fce19b6f", "chrome_app_unittests": "bd6708ff6775a787a94b1804495b3964beba6600", "chromedriver_unittests": "85e07b07ae5fdabd694c905b8927cf257cdb5f3f", "components_browsertests": "492a00938dcae8cb412cd7febfe790c9caf91ef6", "components_unittests": "af47f66ba16432484d8803776be6902736938b70", "compositor_unittests": "fc75840984122747a3542e4914eca0909a2e7cf1", "content_browsertests": "0ce43d7dfd6182b74887564f25e6dc291f21e347", "content_unittests": "83094c2109a4389c8b8d3d6a8d5886a0763a1062", "cronet_tests": "70f62a590fa2723349e507654e4dd67814686c76", "cronet_unittests": "9a976839c420c9b1c0967743d6a4f0140ffcfd3c", "crypto_unittests": "2ae959e43142f1a7165561bca532dcdfe52dfe96", "dbus_unittests": "28453e90b321a2c5afacb6e91e9ad83099e53c15", "device_unittests": "8bddd84790afbdfbec2acb24fe3ea4530e388058", "display_unittests": "f9ef06e042d6997f75ec019f812d4d3d29ad80c9", "events_unittests": "edefa705b88e4e6c7ae4128dce4e4f4a4f494e8d", "extensions_browsertests": "41d1e03a1ff711ba793e3ea2b163d47ee7c61b09", "extensions_unittests": "9b422727ae90514586ab6ca7a0618b6d53d1700f", "filesystem_service_unittests": "0cb638ea21f3cb25c6619b89a10f25abc5441fd8", "gcm_unit_tests": "e0f48c4ba3f4ba13edff836ac8735bd6a8a7d48c", "gfx_unittests": "926ab7ec3040d30cec5d8f0d83ff86a784bf5d0a", "gin_unittests": "51fd7923436d5f507bf717a1ea3e10a425709609", "gl_unittests": "4430054f1e06739b53a46cbd4ab9808d0bed26c2", "google_apis_unittests": "78d0ee01512abbc63dfdd16065684f10f1890a87", "gpu_unittests": "2e77f6c4c448bfc31708c8ff4523e59d3eee8ac9", "headless_browsertests": "24472f0157389af7b7d911ca4021609d6c6e2bf1", "headless_unittests": "d03a9b5c4a42ea34d6a894037ffad5e9e095569a", "interactive_ui_tests": "ae27269f6e5ffb394f181ff377807cd4e58db37c", "ipc_tests": "ec90b18191c09014aabf6f2226c071a8962d1c15", "jingle_unittests": "4c322fae7aceb37a2101a8cad4300758e550fb6a", "latency_unittests": "2868adeb258e67d3a76bccd283b91d2c686a3599", "leveldb_service_unittests": "0e8a9c7c1dfd57d06aadf5c9de6038f8d4c9352f", "libjingle_xmpp_unittests": "8ef6e50e2e4dc333ca8884dc54232e2b0e9e9069", "media_blink_unittests": "a2aa9a5e767b5a9ffb0e126e7c335be59f1bd911", "media_service_unittests": "0f6498294bc41993507f50d3fe9c9ec6a110b4ee", "media_unittests": "8dad22d953f1071e5abd8b7f2a1517c64772d6da", "message_center_unittests": "d4b5e24c980e4a323885726dedddd3d1db893482", "midi_unittests": "6e18d97ba4890fb1f01921973296660dbc761de1", "mojo_core_unittests": "f1673b79b29f075a2793dc31cac29e71b5acb6dd", "mojo_unittests": "c0e19e8e7847fb65a60ea511a5968940684b0b36", "nacl_helper_nonsfi_unittests": "0d861f9fb2d6adde53388df86a65de07890d79c2", "nacl_loader_unittests": "19edec03d0a53ce71e8c7ea36d33c15965ea05ec", "native_theme_unittests": "6d10d1913a21926d6a1d96d8f85192b0087344be", "net_unittests": "d1f8234a14d5041d68583d6c4ea852faebf204ca", "pdf_unittests": "ce5d5679da7c3bf2c192732cbbdcfb2e86b4ef78", "ppapi_unittests": "b7e5da945d1aacd78716d275e207319a83dc36f2", "printing_unittests": "350bb5a373c5b5995a9f463d4c90db0286e4bbfc", "remoting_unittests": "30616f86fe250e7d79f9bfd5ca95550fe1b08e67", "sandbox_linux_unittests": "9ffb7c0b2a7c34773bbb23f21c52aac043eec64c", "service_manager_unittests": "023c2640bea2c2ff3283835394f7843611504aa6", "shell_dialogs_unittests": "c85719364c336ef6ed7b293ca26cb70837abcee7", "skia_unittests": "cfab406a21f83b631e82c16253e4aaa53cf4399f", "snapshot_unittests": "36790e36faffd70ed77c55fcabfd53a5bdde6fb5", "sql_unittests": "661da5b767d67d0a141f831b039616086156a96b", "storage_unittests": "efc190c569da8be94b7e75e4c16412773b9c140b", "sync_integration_tests": "a4b0da9a3c2bc600d11745305df76369eaa58252", "traffic_annotation_auditor_unittests": "f4384285fa084a3b5aeb6ef8c90e1222fd04bb05", "ui_base_unittests": "5f6e27bd982e78a3e558ff54fc9459dadd3e19c0", "ui_touch_selection_unittests": "088212858d2f07004fe6cf7f94be87b5869ad445", "unit_tests": "aa7cb15a5661973275e07892cc9648ad14b48bad", "url_unittests": "bbdfe2050b11961ac9fc990d279d4f19d79c26ac", "views_unittests": "c01deaf6915d5f120488973d178943cb81d40754", "viz_unittests": "8b72b198b734b027f409f816e16845a799162577", "vr_common_unittests": "e0ba97988008c3937e3c14187ed1c962e3678e33", "vr_pixeltests": "2c5a05b7fd40750721fac1ae20b28e27b003cb00", "wm_unittests": "dcb155506fd5ca35fb6fb67bc28f2736e568b937", "wtf_unittests": "0e0c40459abb4d40e8f57601218ea3e438ff884c"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmptIWyRX.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpQNM1TS', '-o', '/b/swarming/w/ir/tmp/t/tmpRT7R4H.json', '/b/swarming/w/ir/tmp/t/tmpQNM1TS/433676236eaca410/output.json'] in None (env: None) Command ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/swarming/resources/standard_gtest_merge.py', '--build-properties', '{"bot_id": "swarm2372-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "user:luci-scheduler@appspot.gserviceaccount.com", "created_ts": 1550980359589551, "id": "8920672934421803088", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux MSan Tests/15179", "builder:Linux MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "gitiles_ref:refs/heads/master", "parent_buildername:Linux MSan Builder", "parent_buildnumber:17448", "scheduler_invocation_id:9086102996586304176", "scheduler_job_id:chromium/Linux MSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux MSan Tests", "buildnumber": 15179, "got_angle_revision": "f78131dac0763e4c2d1310a9560cbd311e5dea64", "got_dawn_revision": "87bf834109fd5d372e62901101f285d4fb65fe67", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "got_revision_cp": "refs/heads/master@{#634985}", "got_swarming_client_revision": "d50a88f50782ba29076061b94c7b9d08a6c7e424", "got_v8_revision": "2f408608876b015b5c40977a6e3bf3984ce8cbe8", "got_v8_revision_cp": "refs/heads/7.4.207@{#1}", "got_webrtc_revision": "8721bb30d86d400a81c9b994e0e1a34a45e7e77b", "got_webrtc_revision_cp": "refs/heads/master@{#26825}", "mastername": "chromium.memory", "parent_buildername": "Linux MSan Builder", "parent_got_angle_revision": "f78131dac0763e4c2d1310a9560cbd311e5dea64", "parent_got_dawn_revision": "87bf834109fd5d372e62901101f285d4fb65fe67", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "parent_got_revision_cp": "refs/heads/master@{#634985}", "parent_got_swarming_client_revision": "d50a88f50782ba29076061b94c7b9d08a6c7e424", "parent_got_v8_revision": "2f408608876b015b5c40977a6e3bf3984ce8cbe8", "parent_got_v8_revision_cp": "refs/heads/7.4.207@{#1}", "parent_got_webrtc_revision": "8721bb30d86d400a81c9b994e0e1a34a45e7e77b", "parent_got_webrtc_revision_cp": "refs/heads/master@{#26825}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "2dc12dbea82e4a6a4875be76b2ff5673cf9dc079", "swarm_hashes": {"accessibility_unittests": "90bbd359d293244647b6945aed752269a1c74543", "angle_unittests": "40a95d65697fc6014cefd698641bf85a74ff3364", "app_shell_unittests": "a35f35c1f5c1714e8037b479390f97d5dd5c8ddf", "aura_unittests": "db6a27a0ae59005c1f435497342bddd5aff7e511", "base_unittests": "548103e04b38b08c3fb3e2562a301d9e71023ccb", "blink_common_unittests": "b05926a8311e85c1600d44b0d382cdf3228e4264", "blink_fuzzer_unittests": "65a11bdf6e2d09db13bde094583e996425422174", "blink_heap_unittests": "a635ba0044fee7c8059076fc21631dd9b2e93cb1", "blink_platform_unittests": "fd6cdcec71de25b73efb700201c2ea3355266bbd", "blink_unittests": "1bc89b758cd719b8c8382345159bb63a85aab134", "boringssl_crypto_tests": "46efeae8d7d0ab5da926529e0312c4f4b53bd753", "boringssl_ssl_tests": "0e94168488e5a6fbaa902424cf945008172a8d9f", "browser_tests": "5b4f162529c163e86039d5928b7a29247cfafcd4", "cacheinvalidation_unittests": "770199c099aa65fd3b11986ba5f9e537f73abb6f", "capture_unittests": "c847615a4f08d250db7a8083701e930f0bd93368", "cast_unittests": "52d2b130879283bb1cf51025f21bb016ac860ea6", "cc_unittests": "69c1c96f053dd9ac740814249eaa3052fce19b6f", "chrome_app_unittests": "bd6708ff6775a787a94b1804495b3964beba6600", "chromedriver_unittests": "85e07b07ae5fdabd694c905b8927cf257cdb5f3f", "components_browsertests": "492a00938dcae8cb412cd7febfe790c9caf91ef6", "components_unittests": "af47f66ba16432484d8803776be6902736938b70", "compositor_unittests": "fc75840984122747a3542e4914eca0909a2e7cf1", "content_browsertests": "0ce43d7dfd6182b74887564f25e6dc291f21e347", "content_unittests": "83094c2109a4389c8b8d3d6a8d5886a0763a1062", "cronet_tests": "70f62a590fa2723349e507654e4dd67814686c76", "cronet_unittests": "9a976839c420c9b1c0967743d6a4f0140ffcfd3c", "crypto_unittests": "2ae959e43142f1a7165561bca532dcdfe52dfe96", "dbus_unittests": "28453e90b321a2c5afacb6e91e9ad83099e53c15", "device_unittests": "8bddd84790afbdfbec2acb24fe3ea4530e388058", "display_unittests": "f9ef06e042d6997f75ec019f812d4d3d29ad80c9", "events_unittests": "edefa705b88e4e6c7ae4128dce4e4f4a4f494e8d", "extensions_browsertests": "41d1e03a1ff711ba793e3ea2b163d47ee7c61b09", "extensions_unittests": "9b422727ae90514586ab6ca7a0618b6d53d1700f", "filesystem_service_unittests": "0cb638ea21f3cb25c6619b89a10f25abc5441fd8", "gcm_unit_tests": "e0f48c4ba3f4ba13edff836ac8735bd6a8a7d48c", "gfx_unittests": "926ab7ec3040d30cec5d8f0d83ff86a784bf5d0a", "gin_unittests": "51fd7923436d5f507bf717a1ea3e10a425709609", "gl_unittests": "4430054f1e06739b53a46cbd4ab9808d0bed26c2", "google_apis_unittests": "78d0ee01512abbc63dfdd16065684f10f1890a87", "gpu_unittests": "2e77f6c4c448bfc31708c8ff4523e59d3eee8ac9", "headless_browsertests": "24472f0157389af7b7d911ca4021609d6c6e2bf1", "headless_unittests": "d03a9b5c4a42ea34d6a894037ffad5e9e095569a", "interactive_ui_tests": "ae27269f6e5ffb394f181ff377807cd4e58db37c", "ipc_tests": "ec90b18191c09014aabf6f2226c071a8962d1c15", "jingle_unittests": "4c322fae7aceb37a2101a8cad4300758e550fb6a", "latency_unittests": "2868adeb258e67d3a76bccd283b91d2c686a3599", "leveldb_service_unittests": "0e8a9c7c1dfd57d06aadf5c9de6038f8d4c9352f", "libjingle_xmpp_unittests": "8ef6e50e2e4dc333ca8884dc54232e2b0e9e9069", "media_blink_unittests": "a2aa9a5e767b5a9ffb0e126e7c335be59f1bd911", "media_service_unittests": "0f6498294bc41993507f50d3fe9c9ec6a110b4ee", "media_unittests": "8dad22d953f1071e5abd8b7f2a1517c64772d6da", "message_center_unittests": "d4b5e24c980e4a323885726dedddd3d1db893482", "midi_unittests": "6e18d97ba4890fb1f01921973296660dbc761de1", "mojo_core_unittests": "f1673b79b29f075a2793dc31cac29e71b5acb6dd", "mojo_unittests": "c0e19e8e7847fb65a60ea511a5968940684b0b36", "nacl_helper_nonsfi_unittests": "0d861f9fb2d6adde53388df86a65de07890d79c2", "nacl_loader_unittests": "19edec03d0a53ce71e8c7ea36d33c15965ea05ec", "native_theme_unittests": "6d10d1913a21926d6a1d96d8f85192b0087344be", "net_unittests": "d1f8234a14d5041d68583d6c4ea852faebf204ca", "pdf_unittests": "ce5d5679da7c3bf2c192732cbbdcfb2e86b4ef78", "ppapi_unittests": "b7e5da945d1aacd78716d275e207319a83dc36f2", "printing_unittests": "350bb5a373c5b5995a9f463d4c90db0286e4bbfc", "remoting_unittests": "30616f86fe250e7d79f9bfd5ca95550fe1b08e67", "sandbox_linux_unittests": "9ffb7c0b2a7c34773bbb23f21c52aac043eec64c", "service_manager_unittests": "023c2640bea2c2ff3283835394f7843611504aa6", "shell_dialogs_unittests": "c85719364c336ef6ed7b293ca26cb70837abcee7", "skia_unittests": "cfab406a21f83b631e82c16253e4aaa53cf4399f", "snapshot_unittests": "36790e36faffd70ed77c55fcabfd53a5bdde6fb5", "sql_unittests": "661da5b767d67d0a141f831b039616086156a96b", "storage_unittests": "efc190c569da8be94b7e75e4c16412773b9c140b", "sync_integration_tests": "a4b0da9a3c2bc600d11745305df76369eaa58252", "traffic_annotation_auditor_unittests": "f4384285fa084a3b5aeb6ef8c90e1222fd04bb05", "ui_base_unittests": "5f6e27bd982e78a3e558ff54fc9459dadd3e19c0", "ui_touch_selection_unittests": "088212858d2f07004fe6cf7f94be87b5869ad445", "unit_tests": "aa7cb15a5661973275e07892cc9648ad14b48bad", "url_unittests": "bbdfe2050b11961ac9fc990d279d4f19d79c26ac", "views_unittests": "c01deaf6915d5f120488973d178943cb81d40754", "viz_unittests": "8b72b198b734b027f409f816e16845a799162577", "vr_common_unittests": "e0ba97988008c3937e3c14187ed1c962e3678e33", "vr_pixeltests": "2c5a05b7fd40750721fac1ae20b28e27b003cb00", "wm_unittests": "dcb155506fd5ca35fb6fb67bc28f2736e568b937", "wtf_unittests": "0e0c40459abb4d40e8f57601218ea3e438ff884c"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmptIWyRX.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpQNM1TS', '-o', '/b/swarming/w/ir/tmp/t/tmpRT7R4H.json', '/b/swarming/w/ir/tmp/t/tmpQNM1TS/433676236eaca410/output.json'] returned exit code 0