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

python -u /b/swarming/w/ir/kitchen-checkout/build/scripts/tools/runit.py --show-path --with-third-party-lib -- python /b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/collect_task.py --verbose -o /b/swarming/w/ir/tmp/t/tmpW2Ap0H.json --task-output-dir /b/swarming/w/ir/tmp/t/tmp7iRsPE --merge-script /b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --merge-script-stdout-file /b/swarming/w/ir/tmp/t/tmpG8RKP4merge_script_log --merge-additional-args '[]' --build-properties '{"bot_id": "swarm2374-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553450761559711, "id": "8918082530205608160", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ChromiumOS MSan Tests/11978", "builder:Linux ChromiumOS MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/d488b3fa47490675ada321f1c0c9752db0f8dc9d", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ChromiumOS MSan Builder", "parent_buildnumber:12148", "scheduler_invocation_id:9083512592302289696", "scheduler_job_id:chromium/Linux ChromiumOS MSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ChromiumOS MSan Tests", "buildnumber": 11978, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "got_revision_cp": "refs/heads/master@{#643730}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.memory", "parent_buildername": "Linux ChromiumOS MSan Builder", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "parent_got_revision_cp": "refs/heads/master@{#643730}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "swarm_hashes": {"accessibility_unittests": "7bd012a6b2906b06ca8b8c950272da4e45dd6d20", "angle_unittests": "c52c3cc0f53c82f8f324c1056570d3818b553800", "app_list_unittests": "70598b0feef9a161da9d9aa9ffec4e83c6e64cc3", "app_shell_unittests": "c29cef573baefd0cd1a6a84f7ca22a3635383a68", "ash_unittests": "db38bd4ccb4c90f0dc6526448f192722bb14430d", "aura_unittests": "dc6c4a7818fe1bacef1720b6114e077e63c17cf8", "base_unittests": "25b137184b42cccbd8a4a12cee2ab9838040c1d3", "blink_common_unittests": "b5579db7de32fe0e39f708506a196b38ae75b838", "blink_fuzzer_unittests": "aea31de8ad3f6b93e45ec48056bf3ca1e8d7c8aa", "blink_heap_unittests": "f49da26f9220686bcc86a8f340806da4ef97e4c0", "blink_platform_unittests": "743256452f43cfb4a96d4d39974b7d291e7244f6", "blink_unittests": "43065f2168809b2eb5e53fc1694bdcf7d3ebd336", "boringssl_crypto_tests": "a67e6f077ae1a403c199ad7ba0ce318e6841327d", "boringssl_ssl_tests": "bc9e48bf93d75c7c0f59ee86ed70ce8f8f43cb7f", "browser_tests": "448f64dc2d342ae3c8df68718e21c65514afdccc", "cacheinvalidation_unittests": "dfdb629dadbcb4a99caf2a4daed54eba122268f7", "capture_unittests": "33dc549ce15dab92cc6b82b1ca602b0b68e624f8", "cast_unittests": "8dedc1bb4b36a626f2736b41ecb772ecdcd8b6a5", "cc_unittests": "198ec8c3ad361e62b3158acb41af3d4833974003", "chrome_app_unittests": "93f3753eb005d934c84930b234f720c8fc217861", "chromedriver_unittests": "3001fdfde512b74818341f60d973a16d4712fdd4", "chromeos_components_unittests": "1de7ab88014735f75ea4ea268a1773c75f149769", "chromeos_unittests": "ecf91478d1410713dd621c775b7449c8034c73d5", "components_browsertests": "6f06d3a5760cd74d6948e804bc61cd8d26cf4d1c", "components_unittests": "54bb7eb35a6afae26bd40c998947ae06a0f0ef9b", "compositor_unittests": "2aa5dbe9c9a5968bf5528ab196b6e65938c8b514", "content_browsertests": "2f4a3f063760200b4967cb441212247435561576", "content_unittests": "f96beb1c9c35994d2927acad32c58c7369b151da", "crypto_unittests": "a6ddf4eaf7ca50466a26875e7a3f0495fa9dfea2", "dbus_unittests": "2fb8268a1dc3830411d4a7a8ea25b37a27f7bd6e", "device_unittests": "56f97491be15bab04c4e51e9767805608859421d", "display_unittests": "5a418294e959b97438ac9d699bf4b3955e912218", "events_unittests": "466456b558fb6930abd7ad00905212cc5a29c8da", "exo_unittests": "db9bf4b01aa35c4c7bad5b84979856aa50f67698", "extensions_browsertests": "905c76e10aa44ba3a8fda8e97823bf9ce90889d5", "extensions_unittests": "be017f803d458a82cf08e15592caf563ce4bc52c", "filesystem_service_unittests": "27b38a614055cf400e5e0f846b8e599c3bfc4f72", "gcm_unit_tests": "5afe49a0d35956f27c590c2a9cf15ccf4168d8f8", "gfx_unittests": "4d579d433aa252e5dbdb63755d742d7ec53f1f99", "gin_unittests": "21084b716a0e77bdd4fc5030545ccf5988a1ee40", "google_apis_unittests": "2a227fec92f772906b8ae7130b513b3bb759583f", "gpu_unittests": "7c8ddcb0f714b64ba50dcea15082a41a3f700a2c", "interactive_ui_tests": "f9a68e9a2aa2042a46b7b25993834cc7321889d0", "ipc_tests": "0d31869097083ee8ac3df9cf6a8216015a3ae896", "jingle_unittests": "3abb80ba9024645a161560f430e47ff29c7ef523", "keyboard_unittests": "d879d2e0b2d0565cdcbac5d8df8438762268b6b5", "latency_unittests": "a09289b1de831aea70c5a796d6f95c7f8111bfe6", "leveldb_service_unittests": "929707937a250ba88b0086ac47e23c16fbad11d8", "libjingle_xmpp_unittests": "04838b119bbbf8bfdf651fd593dc8dc2f495f382", "media_blink_unittests": "fce7e34da3e36b6793eff63d400e0ab270fe2fb1", "media_service_unittests": "3522b7e0479a3f8f692831c91995a6628b3b55cf", "media_unittests": "3bcf2acaf3c0059ae1c7a282ac0918b5ba5ceaa4", "message_center_unittests": "c0e0642be5bb58dc8477e393b10e0e67d27ecb04", "midi_unittests": "1865bd29152cd69018b5beb2b96817e1f72292e5", "mojo_core_unittests": "03467e9fb146053f4230db8c828223640205ec0b", "mojo_unittests": "8400a3868e22c9b34ea3c269e6d67632d751939c", "nacl_helper_nonsfi_unittests": "124837afc2e01073806143411b6322253476e616", "nacl_loader_unittests": "1c4bb067510d32b3b472b7df0164807523f367e6", "native_theme_unittests": "7ed036a4e374d8fec59b14e71a26e6b16f20957b", "net_unittests": "b1e13b48ff32b6d851d304f8a83724a34457aa7d", "ozone_gl_unittests": "59f40d8811469830d0a8b2e1809a8b4c36fdf150", "ozone_unittests": "2758a35cf97cf76cc89f44c65db0852758931d48", "ozone_x11_unittests": "e2dec586be4c6b3403abde2bc12dc32dad4f87d9", "pdf_unittests": "f059caa20b364444617e528dc15ebcf7591861ba", "perfetto_unittests": "17a5cc49f77bbbdee208b68a087cac14447fbdeb", "ppapi_unittests": "78d369c71b7715d88cd7c7c6ac2270b30465ed23", "printing_unittests": "d6199581755af61a38cba334f8b79f80a4145a6c", "remoting_unittests": "76b254ab1720ce40a07570535a5f5f96b3cd329c", "sandbox_linux_unittests": "69089b1c2f76c0ac71edd5b2b8bc172139c5b7c7", "service_manager_unittests": "6f9c3c665aa19fcd3df7411377598d7b7f7287e6", "shell_dialogs_unittests": "e372e2de1550b593776684a1d3ea9c039a3de3f1", "skia_unittests": "96ee2efb7fda4f31287ff0b97c09b2cac4226dac", "snapshot_unittests": "eb39a67b5c2a9db82413eb9229f047b24e8eb106", "sql_unittests": "7f200db1a328186c86265d4d8b029456a14f4920", "storage_unittests": "cba10da115880314dd29f862740836f1e4f35647", "sync_integration_tests": "50f102650ceb536d3db7cee0eeb467f709806338", "traffic_annotation_auditor_unittests": "4ae220629e29c83ad4d0756f487bbe3c7f7fcf8a", "ui_base_unittests": "33d70614d899b83aee748ecb78b8fcf1d9d36dd1", "ui_chromeos_unittests": "b108813cca5c2aa0e1c9f4cbd863331688528724", "ui_touch_selection_unittests": "039fb3d8ad6b7510956251d2b8c8569d7b138922", "unit_tests": "cef25e01a8ad5eecdc8fe46a5fbf436c0982249e", "url_unittests": "a876b3066177c6f9aceaca738f2c5b03229feaf8", "usage_time_limit_unittests": "a2f90164b2cc04390954c466ee4a40c27af5327d", "views_unittests": "9b93f91829f8819c000720330c0c78ece43e337d", "viz_unittests": "922ece5d08fe56fd810cf02152dfd93652fc3d98", "wayland_client_perftests": "8c9c98111d05fba2721dc406e44f601ba769b113", "wm_unittests": "acc8dfa3f5a46cfb3ad5e351ba27e9d6cf3c26d3", "wtf_unittests": "523886a3f60b86ee0d8ecc01b46991e443311c53"}}' --summary-json-file /b/swarming/w/ir/tmp/t/tmpCQtprP.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/tmpPK7voB.json in dir /b/swarming/w/ir/k: allow_subannotations: True cmd: ['python', '-u', '/b/swarming/w/ir/kitchen-checkout/build/scripts/tools/runit.py', '--show-path', '--with-third-party-lib', '--', 'python', '/b/swarming/w/ir/kitchen-checkout/build/scripts/slave/recipe_modules/chromium_swarming/resources/collect_task.py', '--verbose', '-o', '/b/swarming/w/ir/tmp/t/tmpW2Ap0H.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmp7iRsPE', '--merge-script', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--merge-script-stdout-file', '/b/swarming/w/ir/tmp/t/tmpG8RKP4merge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"bot_id": "swarm2374-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553450761559711, "id": "8918082530205608160", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ChromiumOS MSan Tests/11978", "builder:Linux ChromiumOS MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/d488b3fa47490675ada321f1c0c9752db0f8dc9d", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ChromiumOS MSan Builder", "parent_buildnumber:12148", "scheduler_invocation_id:9083512592302289696", "scheduler_job_id:chromium/Linux ChromiumOS MSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ChromiumOS MSan Tests", "buildnumber": 11978, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "got_revision_cp": "refs/heads/master@{#643730}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.memory", "parent_buildername": "Linux ChromiumOS MSan Builder", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "parent_got_revision_cp": "refs/heads/master@{#643730}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "swarm_hashes": {"accessibility_unittests": "7bd012a6b2906b06ca8b8c950272da4e45dd6d20", "angle_unittests": "c52c3cc0f53c82f8f324c1056570d3818b553800", "app_list_unittests": "70598b0feef9a161da9d9aa9ffec4e83c6e64cc3", "app_shell_unittests": "c29cef573baefd0cd1a6a84f7ca22a3635383a68", "ash_unittests": "db38bd4ccb4c90f0dc6526448f192722bb14430d", "aura_unittests": "dc6c4a7818fe1bacef1720b6114e077e63c17cf8", "base_unittests": "25b137184b42cccbd8a4a12cee2ab9838040c1d3", "blink_common_unittests": "b5579db7de32fe0e39f708506a196b38ae75b838", "blink_fuzzer_unittests": "aea31de8ad3f6b93e45ec48056bf3ca1e8d7c8aa", "blink_heap_unittests": "f49da26f9220686bcc86a8f340806da4ef97e4c0", "blink_platform_unittests": "743256452f43cfb4a96d4d39974b7d291e7244f6", "blink_unittests": "43065f2168809b2eb5e53fc1694bdcf7d3ebd336", "boringssl_crypto_tests": "a67e6f077ae1a403c199ad7ba0ce318e6841327d", "boringssl_ssl_tests": "bc9e48bf93d75c7c0f59ee86ed70ce8f8f43cb7f", "browser_tests": "448f64dc2d342ae3c8df68718e21c65514afdccc", "cacheinvalidation_unittests": "dfdb629dadbcb4a99caf2a4daed54eba122268f7", "capture_unittests": "33dc549ce15dab92cc6b82b1ca602b0b68e624f8", "cast_unittests": "8dedc1bb4b36a626f2736b41ecb772ecdcd8b6a5", "cc_unittests": "198ec8c3ad361e62b3158acb41af3d4833974003", "chrome_app_unittests": "93f3753eb005d934c84930b234f720c8fc217861", "chromedriver_unittests": "3001fdfde512b74818341f60d973a16d4712fdd4", "chromeos_components_unittests": "1de7ab88014735f75ea4ea268a1773c75f149769", "chromeos_unittests": "ecf91478d1410713dd621c775b7449c8034c73d5", "components_browsertests": "6f06d3a5760cd74d6948e804bc61cd8d26cf4d1c", "components_unittests": "54bb7eb35a6afae26bd40c998947ae06a0f0ef9b", "compositor_unittests": "2aa5dbe9c9a5968bf5528ab196b6e65938c8b514", "content_browsertests": "2f4a3f063760200b4967cb441212247435561576", "content_unittests": "f96beb1c9c35994d2927acad32c58c7369b151da", "crypto_unittests": "a6ddf4eaf7ca50466a26875e7a3f0495fa9dfea2", "dbus_unittests": "2fb8268a1dc3830411d4a7a8ea25b37a27f7bd6e", "device_unittests": "56f97491be15bab04c4e51e9767805608859421d", "display_unittests": "5a418294e959b97438ac9d699bf4b3955e912218", "events_unittests": "466456b558fb6930abd7ad00905212cc5a29c8da", "exo_unittests": "db9bf4b01aa35c4c7bad5b84979856aa50f67698", "extensions_browsertests": "905c76e10aa44ba3a8fda8e97823bf9ce90889d5", "extensions_unittests": "be017f803d458a82cf08e15592caf563ce4bc52c", "filesystem_service_unittests": "27b38a614055cf400e5e0f846b8e599c3bfc4f72", "gcm_unit_tests": "5afe49a0d35956f27c590c2a9cf15ccf4168d8f8", "gfx_unittests": "4d579d433aa252e5dbdb63755d742d7ec53f1f99", "gin_unittests": "21084b716a0e77bdd4fc5030545ccf5988a1ee40", "google_apis_unittests": "2a227fec92f772906b8ae7130b513b3bb759583f", "gpu_unittests": "7c8ddcb0f714b64ba50dcea15082a41a3f700a2c", "interactive_ui_tests": "f9a68e9a2aa2042a46b7b25993834cc7321889d0", "ipc_tests": "0d31869097083ee8ac3df9cf6a8216015a3ae896", "jingle_unittests": "3abb80ba9024645a161560f430e47ff29c7ef523", "keyboard_unittests": "d879d2e0b2d0565cdcbac5d8df8438762268b6b5", "latency_unittests": "a09289b1de831aea70c5a796d6f95c7f8111bfe6", "leveldb_service_unittests": "929707937a250ba88b0086ac47e23c16fbad11d8", "libjingle_xmpp_unittests": "04838b119bbbf8bfdf651fd593dc8dc2f495f382", "media_blink_unittests": "fce7e34da3e36b6793eff63d400e0ab270fe2fb1", "media_service_unittests": "3522b7e0479a3f8f692831c91995a6628b3b55cf", "media_unittests": "3bcf2acaf3c0059ae1c7a282ac0918b5ba5ceaa4", "message_center_unittests": "c0e0642be5bb58dc8477e393b10e0e67d27ecb04", "midi_unittests": "1865bd29152cd69018b5beb2b96817e1f72292e5", "mojo_core_unittests": "03467e9fb146053f4230db8c828223640205ec0b", "mojo_unittests": "8400a3868e22c9b34ea3c269e6d67632d751939c", "nacl_helper_nonsfi_unittests": "124837afc2e01073806143411b6322253476e616", "nacl_loader_unittests": "1c4bb067510d32b3b472b7df0164807523f367e6", "native_theme_unittests": "7ed036a4e374d8fec59b14e71a26e6b16f20957b", "net_unittests": "b1e13b48ff32b6d851d304f8a83724a34457aa7d", "ozone_gl_unittests": "59f40d8811469830d0a8b2e1809a8b4c36fdf150", "ozone_unittests": "2758a35cf97cf76cc89f44c65db0852758931d48", "ozone_x11_unittests": "e2dec586be4c6b3403abde2bc12dc32dad4f87d9", "pdf_unittests": "f059caa20b364444617e528dc15ebcf7591861ba", "perfetto_unittests": "17a5cc49f77bbbdee208b68a087cac14447fbdeb", "ppapi_unittests": "78d369c71b7715d88cd7c7c6ac2270b30465ed23", "printing_unittests": "d6199581755af61a38cba334f8b79f80a4145a6c", "remoting_unittests": "76b254ab1720ce40a07570535a5f5f96b3cd329c", "sandbox_linux_unittests": "69089b1c2f76c0ac71edd5b2b8bc172139c5b7c7", "service_manager_unittests": "6f9c3c665aa19fcd3df7411377598d7b7f7287e6", "shell_dialogs_unittests": "e372e2de1550b593776684a1d3ea9c039a3de3f1", "skia_unittests": "96ee2efb7fda4f31287ff0b97c09b2cac4226dac", "snapshot_unittests": "eb39a67b5c2a9db82413eb9229f047b24e8eb106", "sql_unittests": "7f200db1a328186c86265d4d8b029456a14f4920", "storage_unittests": "cba10da115880314dd29f862740836f1e4f35647", "sync_integration_tests": "50f102650ceb536d3db7cee0eeb467f709806338", "traffic_annotation_auditor_unittests": "4ae220629e29c83ad4d0756f487bbe3c7f7fcf8a", "ui_base_unittests": "33d70614d899b83aee748ecb78b8fcf1d9d36dd1", "ui_chromeos_unittests": "b108813cca5c2aa0e1c9f4cbd863331688528724", "ui_touch_selection_unittests": "039fb3d8ad6b7510956251d2b8c8569d7b138922", "unit_tests": "cef25e01a8ad5eecdc8fe46a5fbf436c0982249e", "url_unittests": "a876b3066177c6f9aceaca738f2c5b03229feaf8", "usage_time_limit_unittests": "a2f90164b2cc04390954c466ee4a40c27af5327d", "views_unittests": "9b93f91829f8819c000720330c0c78ece43e337d", "viz_unittests": "922ece5d08fe56fd810cf02152dfd93652fc3d98", "wayland_client_perftests": "8c9c98111d05fba2721dc406e44f601ba769b113", "wm_unittests": "acc8dfa3f5a46cfb3ad5e351ba27e9d6cf3c26d3", "wtf_unittests": "523886a3f60b86ee0d8ecc01b46991e443311c53"}}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmpCQtprP.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/tmpPK7voB.json'] env: {'CHROME_HEADLESS': '1'} env_prefixes: {'PATH': '/b/swarming/w/ir/cache/swarming_client'} env_suffixes: {} infra_step: False name_tokens: ('cacheinvalidation_unittests',) ok_ret: ALL_OK 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: 34696 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/8918082530205608160 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/itc8MKR1/luci_context.078653405 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: swarm2374-c4 SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 43c9b308700ff111 TEMP: /b/swarming/w/ir/tmp/t TEMPDIR: /b/swarming/w/ir/tmp/t TERM: linux TMP: /b/swarming/w/ir/tmp/t TMPDIR: /b/swarming/w/ir/tmp/t UPSTART_EVENTS: net-device-up UPSTART_INSTANCE: UPSTART_JOB: chromebuild-startup USER: chrome-bot USERNAME: chrome-bot VPYTHON_VIRTUALENV_ROOT: /b/swarming/w/ir/cache/vpython _: /b/swarming/w/ir/cipd_bin_packages/vpython Set PYTHONPATH: /b/swarming/w/ir/kitchen-checkout/build/scripts:/b/swarming/w/ir/kitchen-checkout/build/site_config:/b/swarming/w/ir/kitchen-checkout/build/third_party:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_8_4p1:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_slave_8_4:/b/swarming/w/ir/kitchen-checkout/build/third_party/coverage-3.7.1:/b/swarming/w/ir/kitchen-checkout/build/third_party/decorator_3_3_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/google_api_python_client:/b/swarming/w/ir/kitchen-checkout/build/third_party/httplib2/python2:/b/swarming/w/ir/kitchen-checkout/build/third_party/infra_libs:/b/swarming/w/ir/kitchen-checkout/build/third_party/jinja2:/b/swarming/w/ir/kitchen-checkout/build/third_party/markupsafe:/b/swarming/w/ir/kitchen-checkout/build/third_party/oauth2client:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1-modules:/b/swarming/w/ir/kitchen-checkout/build/third_party/python-rsa:/b/swarming/w/ir/kitchen-checkout/build/third_party/requests_2_10_0:/b/swarming/w/ir/kitchen-checkout/build/third_party/setuptools-0.6c11:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_migrate_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/tempita_0_5:/b/swarming/w/ir/kitchen-checkout/build/third_party/twisted_10_2:/b/swarming/w/ir/kitchen-checkout/build/third_party/uritemplate:/b/swarming/w/ir/kitchen-checkout/build/third_party/site-packages 2019-03-24 11:12:35,035 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmp7iRsPE' 2019-03-24 11:12:35,036 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmp7iRsPE' already exists! 2019-03-24 11:12:35,036 - root: [WARNING] task_output_dir existing content: [] 2019-03-24 11:12:35,036 - 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/tmpPK7voB.json -output-dir /b/swarming/w/ir/tmp/t/tmp7iRsPE -task-summary-json /b/swarming/w/ir/tmp/t/tmpCQtprP.json [D2019-03-24T11:12:35.044074-07:00 20762 0 auth.go:1265] Minting a new token {"key":"luci_ctx/81ccfbd61043450c444913157412c42c97bcfd72786c1b05633e878ab0e72946", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-24T11:12:35.044167-07:00 20762 0 luci_ctx.go:138] POST http://127.0.0.1:37318/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/81ccfbd61043450c444913157412c42c97bcfd72786c1b05633e878ab0e72946", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-24T11:12:35.047009-07:00 20762 0 auth.go:1222] Token expires in 34m46.953017697s {"key":"luci_ctx/81ccfbd61043450c444913157412c42c97bcfd72786c1b05633e878ab0e72946", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 43c9b6eda3d20c10: exit 0 Additional test environment: CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox CHROME_HEADLESS=1 G_SLICE=always-malloc LANG=en_US.UTF-8 LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer MSAN_OPTIONS=symbolize=0 handle_abort=1 NSS_DISABLE_ARENA_FREE_LIST=1 NSS_DISABLE_UNLOAD=1 Command: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioJVGO52/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 [2963:2963:0324/003223.117142:3788240657:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000520 with delay 0 [2963:2963:0324/003223.117560:3788241029:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000520 [2963:2963:0324/003223.117912:3788241380: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 } [2963:2963:0324/003223.117981:3788241452:INFO:recurring-task.cc(55)] [Startup] Scheduling 2120 with a delay 500000, Now = 210919424 [2963:2963:0324/003223.118029:3788241497:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005c0 with delay 500 [2963:2963:0324/003223.118098:3788241565:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005c0 [2963:2963:0324/003223.118384:3788241853: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 (5 ms) [1/28] ProtocolHandlerTest.SendInitializeOnly (5 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [2963:2963:0324/003223.119671:3788243140:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "fake nonce" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } [ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (0 ms) [2/28] ProtocolHandlerTest.ReceiveTokenControlOnly (0 ms) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes [2963:2963:0324/003223.120228:3788243703:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0 [2963:2963:0324/003223.120350:3788243818:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004e0 with delay 0 [2963:2963:0324/003223.120406:3788243876:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000460 with delay 0 [2963:2963:0324/003223.120480:3788243956:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004a0 with delay 0 [2963:2963:0324/003223.120542:3788244037:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000450 with delay 0 [2963:2963:0324/003223.120638:3788244109:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000490 with delay 0 [2963:2963:0324/003223.121057:3788244534:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0 [2963:2963:0324/003223.121227:3788244697: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 } [2963:2963:0324/003223.121290:3788244758:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2408 with a delay 500000, Now = 210919424 [2963:2963:0324/003223.121338:3788244806:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000610 with delay 500 [2963:2963:0324/003223.121386:3788244853:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004e0 [2963:2963:0324/003223.121431:3788244898:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000460 [2963:2963:0324/003223.121471:3788244940:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004a0 [2963:2963:0324/003223.121514:3788244980:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000450 [2963:2963:0324/003223.121552:3788245018:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000490 [2963:2963:0324/003223.121618:3788245089:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [2963:2963:0324/003223.121683:3788245150:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000610 [2963:2963:0324/003223.121843:3788245311:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [2963:2963:0324/003223.123079:3788246548: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 (5 ms) [3/28] ProtocolHandlerTest.SendMultipleMessageTypes (5 ms) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage [2963:2963:0324/003223.124822:3788248292:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } invalidation_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } } registration_status_message: { registration_status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } } registration_sync_request_message: { } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } [ OK ] ProtocolHandlerTest.IncomingCompositeMessage (1 ms) [4/28] ProtocolHandlerTest.IncomingCompositeMessage (1 ms) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage [2963:2963:0324/003223.125578:3788249047: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 } } [2963:2963:0324/003223.125670:3788249138: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" } [2963:2963:0324/003223.125766:3788249233: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 } } [2963:2963:0324/003223.125865:3788249332:ERROR:protocol-handler.cc(145)] Received invalid message: { header: { client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } [ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms) [5/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch [2963:2963:0324/003223.126421:3788249890: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 } } [2963:2963:0324/003223.126549:3788250016: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 (0 ms) [6/28] ProtocolHandlerTest.MajorVersionMismatch (0 ms) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch [2963:2963:0324/003223.127067:3788250535:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 4 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.MinorVersionMismatch (1 ms) [7/28] ProtocolHandlerTest.MinorVersionMismatch (1 ms) [ RUN ] ProtocolHandlerTest.ConfigMessage [2963:2963:0324/003223.127611:3788251080: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" } } [2963:2963:0324/003223.127681:3788251149:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000003e0 with delay 0 [2963:2963:0324/003223.127726:3788251193:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000003e0 [2963:2963:0324/003223.127812:3788251280: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 } [2963:2963:0324/003223.127866:3788251334:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2792 with a delay 500000, Now = 210919424 [2963:2963:0324/003223.127910:3788251377:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000003f0 with delay 500 [2963:2963:0324/003223.127965:3788251441:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000003f0 [2963:2963:0324/003223.128016:3788251483: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 [2963:2963:0324/003223.174522:3788297993:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.ErrorMessage (0 ms) [9/28] ProtocolHandlerTest.ErrorMessage (0 ms) [ RUN ] ProtocolHandlerTest.TokenMismatch [2963:2963:0324/003223.175081:3788298549:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.TokenMismatch (1 ms) [10/28] ProtocolHandlerTest.TokenMismatch (1 ms) [ RUN ] InvalidationClientImplTest.Start [2961:2961:0324/003223.098237:3788221751:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000620 with delay 0 [2961:2961:0324/003223.098719:3788222188:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2961:2961:0324/003223.099270:3788222739:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000800 with delay 0 [2961:2961:0324/003223.099358:3788222864:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000620 [2961:2961:0324/003223.099443:3788222911:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000800 [2961:2961:0324/003223.099659:3788223128:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2961:2961:0324/003223.099941:3788223411:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000850 with delay 0 [2961:2961:0324/003223.100061:3788223529:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000850 [2961:2961:0324/003223.100128:3788223599:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2961:2961:0324/003223.100178:3788223678:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000800 with delay 0 [2961:2961:0324/003223.100257:3788223725:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000800 [2961:2961:0324/003223.100346:3788223824:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2961:2961:0324/003223.100415:3788223885:INFO:recurring-task.cc(55)] [Startup] Scheduling 2120 with a delay 0, Now = 210919424 [2961:2961:0324/003223.100464:3788223931:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000850 with delay 0 [2961:2961:0324/003223.100517:3788223985:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000850 [2961:2961:0324/003223.100810:3788224279:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "3615392383166341584" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2961:2961:0324/003223.100866:3788224334:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2504 with a delay 500000, Now = 210919424 [2961:2961:0324/003223.100916:3788224383:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000800 with delay 500 [2961:2961:0324/003223.100962:3788224431:INFO:recurring-task.cc(55)] [Retry] Scheduling 2120 with a delay 60000000, Now = 210919424 [2961:2961:0324/003223.101008:3788224480:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007c0 with delay 60000 [2961:2961:0324/003223.101070:3788224537:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000800 [2961:2961:0324/003223.101166:3788224634:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.101274:3788224741:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.101472:3788224940: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: "3615392383166341584" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2961:2961:0324/003223.101817:3788225286:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000800 with delay 0 [2961:2961:0324/003223.101867:3788225344:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000800 [2961:2961:0324/003223.102112:3788225592:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "3615392383166341584" 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" } } [2961:2961:0324/003223.102206:3788225674:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "3615392383166341584" [2961:2961:0324/003223.102285:3788225753:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2961:2961:0324/003223.102339:3788225807:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [2961:2961:0324/003223.102383:3788225850:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000840 with delay 1200000 [2961:2961:0324/003223.102429:3788225896:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2961:2961:0324/003223.102701:3788226169:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2961:2961:0324/003223.102751:3788226220:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 904 with a delay 0, Now = 211419424 [2961:2961:0324/003223.102793:3788226260:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000850 with delay 0 [2961:2961:0324/003223.102860:3788226327: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 [2961:2961:0324/003223.102914:3788226381:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000850 [2961:2961:0324/003223.103045:3788226513:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000870 with delay 0 [2961:2961:0324/003223.103103:3788226570:INFO:recurring-task.cc(55)] [Retry] Scheduling 904 with a delay 10000000, Now = 211419424 [2961:2961:0324/003223.103157:3788226624:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000620 with delay 10000 [2961:2961:0324/003223.103197:3788226664:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000870 [2961:2961:0324/003223.103234:3788226701:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (9 ms) [11/28] InvalidationClientImplTest.Start (9 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [2961:2961:0324/003223.104056:3788227530:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 0 [2961:2961:0324/003223.104148:3788227616: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 [2961:2961:0324/003223.104724:3788228193:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000830 with delay 0 [2961:2961:0324/003223.104793:3788228260:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2961:2961:0324/003223.105240:3788228708:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000890 with delay 0 [2961:2961:0324/003223.105291:3788228759:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000830 [2961:2961:0324/003223.105340:3788228807:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000890 [2961:2961:0324/003223.105413:3788228883:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2961:2961:0324/003223.105491:3788228967:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008d0 with delay 0 [2961:2961:0324/003223.105554:3788229022:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008d0 [2961:2961:0324/003223.105595:3788229063:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2961:2961:0324/003223.105635:3788229103:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000890 with delay 0 [2961:2961:0324/003223.105681:3788229148:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000890 [2961:2961:0324/003223.105719:3788229186:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2961:2961:0324/003223.105765:3788229232:INFO:recurring-task.cc(55)] [Startup] Scheduling 2600 with a delay 0, Now = 210919424 [2961:2961:0324/003223.105803:3788229271:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008d0 with delay 0 [2961:2961:0324/003223.105845:3788229312:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008d0 [2961:2961:0324/003223.105919:3788229386:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-2839232980790330387" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2961:2961:0324/003223.105965:3788229433:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2120 with a delay 500000, Now = 210919424 [2961:2961:0324/003223.106004:3788229474:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000890 with delay 500 [2961:2961:0324/003223.106052:3788229520:INFO:recurring-task.cc(55)] [Retry] Scheduling 2600 with a delay 60000000, Now = 210919424 [2961:2961:0324/003223.106093:3788229560:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008b0 with delay 60000 [2961:2961:0324/003223.106157:3788229625:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000890 [2961:2961:0324/003223.106200:3788229668:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.106253:3788229720:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.106397:3788229864: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: "-2839232980790330387" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2961:2961:0324/003223.106536:3788230004:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000890 with delay 0 [2961:2961:0324/003223.106583:3788230050:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000890 [2961:2961:0324/003223.106713:3788230181:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-2839232980790330387" 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" } } [2961:2961:0324/003223.106777:3788230245:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-2839232980790330387" [2961:2961:0324/003223.106827:3788230295:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2961:2961:0324/003223.106875:3788230343:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [2961:2961:0324/003223.106916:3788230388:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008c0 with delay 1200000 [2961:2961:0324/003223.106963:3788230431:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2961:2961:0324/003223.107097:3788230565:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2961:2961:0324/003223.107157:3788230625:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424 [2961:2961:0324/003223.107204:3788230672:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008d0 with delay 0 [2961:2961:0324/003223.107264:3788230732: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 [2961:2961:0324/003223.107316:3788230783:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008d0 [2961:2961:0324/003223.107391:3788230859:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008f0 with delay 0 [2961:2961:0324/003223.107443:3788230910:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424 [2961:2961:0324/003223.107484:3788230951:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000830 with delay 10000 [2961:2961:0324/003223.107532:3788230999:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008f0 [2961:2961:0324/003223.107569:3788231038:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2961:2961:0324/003223.107657:3788231125:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000008f0 with delay 0 [2961:2961:0324/003223.107705:3788231172:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000008f0 [2961:2961:0324/003223.107759:3788231226:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [2961:2961:0324/003223.107808:3788231275:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [2961:2961:0324/003223.107853:3788231320:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [2961:2961:0324/003223.107984:3788231454:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 2120 with a delay 500000, Now = 211469424 [2961:2961:0324/003223.108033:3788231501:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000008d0 with delay 500 [2961:2961:0324/003223.108077:3788231545:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 2792 with a delay 60000000, Now = 211469424 [2961:2961:0324/003223.108115:3788231596:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000008e0 with delay 60000 [2961:2961:0324/003223.108192:3788231665:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000008d0 [2961:2961:0324/003223.108261:3788231731:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.108328:3788231795:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.108367:3788231834:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2961:2961:0324/003223.108582:3788232051: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 } } } [2961:2961:0324/003223.108695:3788232163:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.108886:3788232355:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7010000008d0 with delay 0 [2961:2961:0324/003223.108931:3788232399:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000008d0 [2961:2961:0324/003223.109192:3788232660: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 } } } } [2961:2961:0324/003223.109372:3788232843: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 [2961:2961:0324/003223.109482:3788232950:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [2961:2961:0324/003223.109623:3788233091:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [2961:2961:0324/003223.109722:3788233190:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [2961:2961:0324/003223.110064:3788233533:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000830 [ OK ] InvalidationClientImplTest.Register (7 ms) [13/28] InvalidationClientImplTest.Register (7 ms) [ RUN ] InvalidationClientImplTest.Invalidations [2961:2961:0324/003223.111883:3788235352:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000770 with delay 0 [2961:2961:0324/003223.111957:3788235424:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2961:2961:0324/003223.112451:3788235921:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005d0 with delay 0 [2961:2961:0324/003223.112518:3788235986:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000770 [2961:2961:0324/003223.112593:3788236067:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000005d0 [2961:2961:0324/003223.112682:3788236150:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2961:2961:0324/003223.112751:3788236218:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008f0 with delay 0 [2961:2961:0324/003223.112802:3788236270:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008f0 [2961:2961:0324/003223.112841:3788236308:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2961:2961:0324/003223.112882:3788236350:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005d0 with delay 0 [2961:2961:0324/003223.112922:3788236389:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000005d0 [2961:2961:0324/003223.112960:3788236427:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2961:2961:0324/003223.113014:3788236482:INFO:recurring-task.cc(55)] [Startup] Scheduling 2696 with a delay 0, Now = 210919424 [2961:2961:0324/003223.113057:3788236524:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008f0 with delay 0 [2961:2961:0324/003223.113096:3788236564:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008f0 [2961:2961:0324/003223.113187:3788236655:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-9221452888028141075" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2961:2961:0324/003223.113235:3788236702:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2984 with a delay 500000, Now = 210919424 [2961:2961:0324/003223.113276:3788236744:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005d0 with delay 500 [2961:2961:0324/003223.113320:3788236788:INFO:recurring-task.cc(55)] [Retry] Scheduling 2696 with a delay 60000000, Now = 210919424 [2961:2961:0324/003223.113361:3788236829:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000540 with delay 60000 [2961:2961:0324/003223.113416:3788236883:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005d0 [2961:2961:0324/003223.113456:3788236923:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.113517:3788236985:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.113664:3788237131: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: "-9221452888028141075" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2961:2961:0324/003223.113796:3788237264:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005d0 with delay 0 [2961:2961:0324/003223.113842:3788237309:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005d0 [2961:2961:0324/003223.113970:3788237437:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-9221452888028141075" 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" } } [2961:2961:0324/003223.114038:3788237506:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-9221452888028141075" [2961:2961:0324/003223.114081:3788237548:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2961:2961:0324/003223.114141:3788237609:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [2961:2961:0324/003223.114185:3788237652:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000890 with delay 1200000 [2961:2961:0324/003223.114226:3788237695:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2961:2961:0324/003223.114357:3788237825:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2961:2961:0324/003223.114400:3788237868:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1416 with a delay 0, Now = 211419424 [2961:2961:0324/003223.114442:3788237910:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008f0 with delay 0 [2961:2961:0324/003223.114516:3788237984: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 [2961:2961:0324/003223.114575:3788238042:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008f0 [2961:2961:0324/003223.114653:3788238120:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000920 with delay 0 [2961:2961:0324/003223.114703:3788238173:INFO:recurring-task.cc(55)] [Retry] Scheduling 1416 with a delay 10000000, Now = 211419424 [2961:2961:0324/003223.114745:3788238212:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000770 with delay 10000 [2961:2961:0324/003223.114785:3788238252:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000920 [2961:2961:0324/003223.114822:3788238289:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2961:2961:0324/003223.114880:3788238347:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.114955:3788238423:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000920 with delay 0 [2961:2961:0324/003223.114997:3788238467:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000920 [2961:2961:0324/003223.115234:3788238702: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 } } } [2961:2961:0324/003223.115333:3788238801: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 [2961:2961:0324/003223.115425:3788238901: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" } [2961:2961:0324/003223.115594:3788239062:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [2961:2961:0324/003223.115704:3788239171:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [2961:2961:0324/003223.115803:3788239270:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000920 with delay 0 [2961:2961:0324/003223.115847:3788239314:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7010000008f0 with delay 0 [2961:2961:0324/003223.115888:3788239355:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000900 with delay 0 [2961:2961:0324/003223.115926:3788239393:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000920 [2961:2961:0324/003223.115984:3788239452:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 2984 with a delay 500000, Now = 211519424 [2961:2961:0324/003223.116029:3788239497:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7010000005d0 with delay 500 [2961:2961:0324/003223.116074:3788239541:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7010000008f0 [2961:2961:0324/003223.116132:3788239600:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000900 [2961:2961:0324/003223.116193:3788239660:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x7010000005d0 [2961:2961:0324/003223.116239:3788239714:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.116313:3788239781:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.116357:3788239824:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2961:2961:0324/003223.116599:3788240071:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777601100 max_known_server_time_ms: 314159265 message_id: "2" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } } } [ OK ] InvalidationClientImplTest.Invalidations (6 ms) [14/28] InvalidationClientImplTest.Invalidations (6 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [2961:2961:0324/003223.117415:3788240884:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000860 with delay 0 [2961:2961:0324/003223.117486:3788240954:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2961:2961:0324/003223.117734:3788241202:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006c0 with delay 0 [2961:2961:0324/003223.117785:3788241253:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000860 [2961:2961:0324/003223.117825:3788241291:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006c0 [2961:2961:0324/003223.117899:3788241366:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2961:2961:0324/003223.117963:3788241431:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008d0 with delay 0 [2961:2961:0324/003223.118016:3788241483:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008d0 [2961:2961:0324/003223.118055:3788241530:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2961:2961:0324/003223.118109:3788241591:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006c0 with delay 0 [2961:2961:0324/003223.118165:3788241633:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006c0 [2961:2961:0324/003223.118205:3788241673:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2961:2961:0324/003223.118249:3788241717:INFO:recurring-task.cc(55)] [Startup] Scheduling 2600 with a delay 0, Now = 210919424 [2961:2961:0324/003223.118291:3788241758:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008d0 with delay 0 [2961:2961:0324/003223.118330:3788241797:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008d0 [2961:2961:0324/003223.118406:3788241874:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1901061889552771097" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2961:2961:0324/003223.118452:3788241920:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 3464 with a delay 500000, Now = 210919424 [2961:2961:0324/003223.118494:3788241968:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006c0 with delay 500 [2961:2961:0324/003223.118541:3788242010:INFO:recurring-task.cc(55)] [Retry] Scheduling 2600 with a delay 60000000, Now = 210919424 [2961:2961:0324/003223.118582:3788242049:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006f0 with delay 60000 [2961:2961:0324/003223.118641:3788242108:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006c0 [2961:2961:0324/003223.118681:3788242153:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.118737:3788242205:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.118908:3788242377: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: "1901061889552771097" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2961:2961:0324/003223.119032:3788242501:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000006c0 with delay 0 [2961:2961:0324/003223.119081:3788242557:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006c0 [2961:2961:0324/003223.119238:3788242706:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1901061889552771097" 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" } } [2961:2961:0324/003223.119303:3788242770:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1901061889552771097" [2961:2961:0324/003223.119345:3788242814:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2961:2961:0324/003223.119390:3788242858:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [2961:2961:0324/003223.119434:3788242902:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005a0 with delay 1200000 [2961:2961:0324/003223.119479:3788242946:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2961:2961:0324/003223.119619:3788243087:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2961:2961:0324/003223.119666:3788243133:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424 [2961:2961:0324/003223.119705:3788243172:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008d0 with delay 0 [2961:2961:0324/003223.119772:3788243242: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 [2961:2961:0324/003223.119829:3788243296:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008d0 [2961:2961:0324/003223.119904:3788243372:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005c0 with delay 0 [2961:2961:0324/003223.119956:3788243424:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424 [2961:2961:0324/003223.119995:3788243466:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000860 with delay 10000 [2961:2961:0324/003223.120041:3788243508:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005c0 [2961:2961:0324/003223.120078:3788243545:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2961:2961:0324/003223.120148:3788243619:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.120213:3788243681:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000005c0 with delay 0 [2961:2961:0324/003223.120259:3788243727:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000005c0 [2961:2961:0324/003223.120407:3788243875: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 } } [2961:2961:0324/003223.120511:3788243979: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 [2961:2961:0324/003223.120592:3788244062:INFO:protocol-handler.cc(294)] Adding subtree: { } [2961:2961:0324/003223.120642:3788244112:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 3464 with a delay 500000, Now = 211469424 [2961:2961:0324/003223.120690:3788244158:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000008d0 with delay 500 [2961:2961:0324/003223.120735:3788244211:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [2961:2961:0324/003223.121001:3788244473: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 } [2961:2961:0324/003223.121088:3788244558:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000008d0 [2961:2961:0324/003223.121146:3788244614:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.121227:3788244696:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.121269:3788244736:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2961:2961:0324/003223.122484:3788245953: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 } } [2961:2961:0324/003223.122834:3788246302:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000860 [ OK ] InvalidationClientImplTest.ServerRequests (7 ms) [15/28] InvalidationClientImplTest.ServerRequests (7 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [2961:2961:0324/003223.124534:3788248024:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004f0 with delay 0 [2961:2961:0324/003223.124641:3788248109:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2961:2961:0324/003223.124940:3788248409:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006c0 with delay 0 [2961:2961:0324/003223.124989:3788248457:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004f0 [2961:2961:0324/003223.125036:3788248503:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006c0 [2961:2961:0324/003223.125111:3788248591:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2961:2961:0324/003223.125194:3788248662:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000480 with delay 0 [2961:2961:0324/003223.125249:3788248717:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000480 [2961:2961:0324/003223.125288:3788248755:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2961:2961:0324/003223.125329:3788248796:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006c0 with delay 0 [2961:2961:0324/003223.125370:3788248837:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006c0 [2961:2961:0324/003223.125407:3788248874:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2961:2961:0324/003223.125450:3788248917:INFO:recurring-task.cc(55)] [Startup] Scheduling 2984 with a delay 0, Now = 210919424 [2961:2961:0324/003223.125491:3788248958:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000480 with delay 0 [2961:2961:0324/003223.125555:3788249022:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000480 [2961:2961:0324/003223.125633:3788249100:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-3358436094001469644" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2961:2961:0324/003223.125679:3788249146:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2600 with a delay 500000, Now = 210919424 [2961:2961:0324/003223.125721:3788249188:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006c0 with delay 500 [2961:2961:0324/003223.125767:3788249234:INFO:recurring-task.cc(55)] [Retry] Scheduling 2984 with a delay 60000000, Now = 210919424 [2961:2961:0324/003223.125806:3788249273:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000470 with delay 60000 [2961:2961:0324/003223.125860:3788249327:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006c0 [2961:2961:0324/003223.125901:3788249368:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.125954:3788249421:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.126098:3788249566: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: "-3358436094001469644" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2961:2961:0324/003223.126246:3788249715:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000006c0 with delay 0 [2961:2961:0324/003223.126294:3788249761:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006c0 [2961:2961:0324/003223.126428:3788249895:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-3358436094001469644" 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" } } [2961:2961:0324/003223.126493:3788249970:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-3358436094001469644" [2961:2961:0324/003223.126551:3788250018:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2961:2961:0324/003223.126595:3788250062:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [2961:2961:0324/003223.126640:3788250108:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004d0 with delay 1200000 [2961:2961:0324/003223.126684:3788250151:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2961:2961:0324/003223.126817:3788250285:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2961:2961:0324/003223.126862:3788250330:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424 [2961:2961:0324/003223.126901:3788250368:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000480 with delay 0 [2961:2961:0324/003223.126962:3788250429: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 [2961:2961:0324/003223.127015:3788250482:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000480 [2961:2961:0324/003223.127092:3788250560:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000380 with delay 0 [2961:2961:0324/003223.127156:3788250624:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424 [2961:2961:0324/003223.127196:3788250665:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004f0 with delay 10000 [2961:2961:0324/003223.127236:3788250703:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000380 [2961:2961:0324/003223.127273:3788250740:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2961:2961:0324/003223.127331:3788250798:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.127388:3788250856:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000380 with delay 0 [2961:2961:0324/003223.127429:3788250897:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000380 [2961:2961:0324/003223.127559:3788251026: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" } } [2961:2961:0324/003223.127638:3788251106: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 [2961:2961:0324/003223.127681:3788251151:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [2961:2961:0324/003223.128045:3788251513:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7010000004f0 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (5 ms) [16/28] InvalidationClientImplTest.IncomingErrorMessage (5 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [2961:2961:0324/003223.129759:3788253228:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000740 with delay 0 [2961:2961:0324/003223.129831:3788253298:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2961:2961:0324/003223.130193:3788253662:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 0 [2961:2961:0324/003223.130246:3788253714:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000740 [2961:2961:0324/003223.130286:3788253752:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000820 [2961:2961:0324/003223.130361:3788253829:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2961:2961:0324/003223.130437:3788253906:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000900 with delay 0 [2961:2961:0324/003223.130493:3788253968:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000900 [2961:2961:0324/003223.130541:3788254008:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2961:2961:0324/003223.130583:3788254050:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 0 [2961:2961:0324/003223.130628:3788254095:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000820 [2961:2961:0324/003223.130666:3788254135:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2961:2961:0324/003223.130711:3788254179:INFO:recurring-task.cc(55)] [Startup] Scheduling 2696 with a delay 0, Now = 210919424 [2961:2961:0324/003223.130756:3788254224:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000900 with delay 0 [2961:2961:0324/003223.130796:3788254263:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000900 [2961:2961:0324/003223.130875:3788254345:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "227079018968583465" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2961:2961:0324/003223.130929:3788254397:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2984 with a delay 500000, Now = 210919424 [2961:2961:0324/003223.130971:3788254439:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 500 [2961:2961:0324/003223.131013:3788254483:INFO:recurring-task.cc(55)] [Retry] Scheduling 2696 with a delay 60000000, Now = 210919424 [2961:2961:0324/003223.131055:3788254522:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005d0 with delay 60000 [2961:2961:0324/003223.131107:3788254585:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000820 [2961:2961:0324/003223.131159:3788254629:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.131213:3788254681:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.131352:3788254834: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: "227079018968583465" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2961:2961:0324/003223.131490:3788254966:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000820 with delay 0 [2961:2961:0324/003223.131543:3788255010:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000820 [2961:2961:0324/003223.131675:3788255143:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "227079018968583465" 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" } } [2961:2961:0324/003223.131744:3788255212:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "227079018968583465" [2961:2961:0324/003223.131787:3788255255:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2961:2961:0324/003223.131832:3788255300:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [2961:2961:0324/003223.131875:3788255343:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008f0 with delay 1200000 [2961:2961:0324/003223.131920:3788255387:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2961:2961:0324/003223.132051:3788255519:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2961:2961:0324/003223.132094:3788255564:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424 [2961:2961:0324/003223.132154:3788255622:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000900 with delay 0 [2961:2961:0324/003223.132215:3788255682: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 [2961:2961:0324/003223.132267:3788255734:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000900 [2961:2961:0324/003223.132343:3788255811:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000910 with delay 0 [2961:2961:0324/003223.132395:3788255862:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424 [2961:2961:0324/003223.132434:3788255901:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000740 with delay 10000 [2961:2961:0324/003223.132475:3788255942:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000910 [2961:2961:0324/003223.132519:3788255986:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2961:2961:0324/003223.132613:3788256083:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000910 with delay 0 [2961:2961:0324/003223.132661:3788256128:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000910 [2961:2961:0324/003223.132718:3788256185:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [2961:2961:0324/003223.132783:3788256251:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 2984 with a delay 500000, Now = 211469424 [2961:2961:0324/003223.132826:3788256294:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000900 with delay 500 [2961:2961:0324/003223.132869:3788256336:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 2120 with a delay 60000000, Now = 211469424 [2961:2961:0324/003223.132907:3788256375:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000920 with delay 60000 [2961:2961:0324/003223.132965:3788256443:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000900 [2961:2961:0324/003223.133026:3788256494:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.133081:3788256548:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.133134:3788256602:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2961:2961:0324/003223.133279:3788256746: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 } } } [2961:2961:0324/003223.133384:3788256853:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.133448:3788256922:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000900 with delay 0 [2961:2961:0324/003223.133496:3788256973:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000900 [2961:2961:0324/003223.133627:3788257094: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" } } [2961:2961:0324/003223.133715:3788257183: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 [2961:2961:0324/003223.133763:3788257231:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [2961:2961:0324/003223.133864:3788257332:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [2961:2961:0324/003223.134193:3788257661:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000740 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms) [17/28] InvalidationClientImplTest.IncomingAuthErrorMessage (6 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [2961:2961:0324/003223.135821:3788259289:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005c0 with delay 0 [2961:2961:0324/003223.135891:3788259359:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2961:2961:0324/003223.136149:3788259618:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004f0 with delay 0 [2961:2961:0324/003223.136198:3788259666:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000005c0 [2961:2961:0324/003223.136241:3788259708:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004f0 [2961:2961:0324/003223.136313:3788259781:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2961:2961:0324/003223.136384:3788259852:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007d0 with delay 0 [2961:2961:0324/003223.136433:3788259900:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000007d0 [2961:2961:0324/003223.136471:3788259940:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2961:2961:0324/003223.136520:3788259987:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004f0 with delay 0 [2961:2961:0324/003223.136594:3788260063:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004f0 [2961:2961:0324/003223.136638:3788260105:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2961:2961:0324/003223.136682:3788260152:INFO:recurring-task.cc(55)] [Startup] Scheduling 2888 with a delay 0, Now = 210919424 [2961:2961:0324/003223.136724:3788260192:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007d0 with delay 0 [2961:2961:0324/003223.136767:3788260234:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000007d0 [2961:2961:0324/003223.136842:3788260317:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "3145009066511244932" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2961:2961:0324/003223.136905:3788260376:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2696 with a delay 500000, Now = 210919424 [2961:2961:0324/003223.136949:3788260416:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004f0 with delay 500 [2961:2961:0324/003223.136989:3788260457:INFO:recurring-task.cc(55)] [Retry] Scheduling 2888 with a delay 60000000, Now = 210919424 [2961:2961:0324/003223.137033:3788260501:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005f0 with delay 60000 [2961:2961:0324/003223.137085:3788260553:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004f0 [2961:2961:0324/003223.137140:3788260608:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.137196:3788260663:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.137359:3788260827: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: "3145009066511244932" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2961:2961:0324/003223.137492:3788260969:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004f0 with delay 0 [2961:2961:0324/003223.137548:3788261015:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004f0 [2961:2961:0324/003223.137674:3788261142:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "3145009066511244932" 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" } } [2961:2961:0324/003223.137735:3788261203:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "3145009066511244932" [2961:2961:0324/003223.137780:3788261247:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2961:2961:0324/003223.137836:3788261304:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [2961:2961:0324/003223.137878:3788261345:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000890 with delay 1200000 [2961:2961:0324/003223.137922:3788261389:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2961:2961:0324/003223.138059:3788261527:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2961:2961:0324/003223.138109:3788261588:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424 [2961:2961:0324/003223.138166:3788261633:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000007d0 with delay 0 [2961:2961:0324/003223.138226:3788261694: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 [2961:2961:0324/003223.138277:3788261744:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000007d0 [2961:2961:0324/003223.138355:3788261823:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000003f0 with delay 0 [2961:2961:0324/003223.138407:3788261875:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424 [2961:2961:0324/003223.138448:3788261915:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005c0 with delay 10000 [2961:2961:0324/003223.138493:3788261968:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000003f0 [2961:2961:0324/003223.138540:3788262007:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2961:2961:0324/003223.138601:3788262068:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000003f0 with delay 0 [2961:2961:0324/003223.138644:3788262111:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000003f0 [2961:2961:0324/003223.138697:3788262164:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [2961:2961:0324/003223.138764:3788262231:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 2696 with a delay 500000, Now = 211469424 [2961:2961:0324/003223.138804:3788262273:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000007d0 with delay 500 [2961:2961:0324/003223.138847:3788262314:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 2504 with a delay 60000000, Now = 211469424 [2961:2961:0324/003223.138887:3788262355:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000490 with delay 60000 [2961:2961:0324/003223.138945:3788262412:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000007d0 [2961:2961:0324/003223.138985:3788262454:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.139043:3788262518:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.139099:3788262569:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2961:2961:0324/003223.139257:3788262730: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 } } } [2961:2961:0324/003223.139578:3788263046:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7010000005c0 [2961:2961:0324/003223.140809:3788264277:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7010000005f0 [2961:2961:0324/003223.140867:3788264333:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x701000000490 [2961:2961:0324/003223.140929:3788264397: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 [2961:2961:0324/003223.140975:3788264443:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [2961:2961:0324/003223.141064:3788264532: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 } [2961:2961:0324/003223.141110:3788264588:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2696 with a delay 500000, Now = 271469424 [2961:2961:0324/003223.141165:3788264632:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7010000005f0 with delay 500 [2961:2961:0324/003223.141206:3788264674:INFO:recurring-task.cc(55)] [Retry] Scheduling 2504 with a delay 60000000, Now = 271469424 [2961:2961:0324/003223.141245:3788264714:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7010000005c0 with delay 60000 [2961:2961:0324/003223.141298:3788264766:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x7010000005f0 [2961:2961:0324/003223.141340:3788264807:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.141395:3788264863:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.141443:3788264910:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2961:2961:0324/003223.141602:3788265069:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 1 registration_digest: "\327\003\047\242\324@\3740-O\354\3229\352\000\231\340\204\224\323" } client_time_ms: 777661050 max_known_server_time_ms: 314159265 message_id: "3" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "InvClientTest" } server_registration_summary_requested: true } } [ OK ] InvalidationClientImplTest.NetworkTimeouts (8 ms) [18/28] InvalidationClientImplTest.NetworkTimeouts (8 ms) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary [2961:2961:0324/003223.143543:3788267012:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007e0 with delay 0 [2961:2961:0324/003223.143614:3788267081:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2961:2961:0324/003223.143857:3788267325:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0 [2961:2961:0324/003223.143904:3788267372:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000007e0 [2961:2961:0324/003223.143944:3788267410:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0 [2961:2961:0324/003223.144026:3788267494:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2961:2961:0324/003223.144092:3788267560:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000490 with delay 0 [2961:2961:0324/003223.144159:3788267627:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000490 [2961:2961:0324/003223.144198:3788267665:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2961:2961:0324/003223.144240:3788267707:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0 [2961:2961:0324/003223.144280:3788267747:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0 [2961:2961:0324/003223.144317:3788267789:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2961:2961:0324/003223.144365:3788267832:INFO:recurring-task.cc(55)] [Startup] Scheduling 3464 with a delay 0, Now = 210919424 [2961:2961:0324/003223.144406:3788267873:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000490 with delay 0 [2961:2961:0324/003223.144445:3788267912:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000490 [2961:2961:0324/003223.144526:3788267994:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1586014730332081298" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2961:2961:0324/003223.144664:3788268132:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 3080 with a delay 500000, Now = 210919424 [2961:2961:0324/003223.144710:3788268177:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 500 [2961:2961:0324/003223.144749:3788268216:INFO:recurring-task.cc(55)] [Retry] Scheduling 3464 with a delay 60000000, Now = 210919424 [2961:2961:0324/003223.144789:3788268271:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000780 with delay 60000 [2961:2961:0324/003223.144860:3788268328:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004b0 [2961:2961:0324/003223.144900:3788268367:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.144958:3788268426:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.145107:3788268586: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: "1586014730332081298" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2961:2961:0324/003223.145243:3788268713:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004b0 with delay 0 [2961:2961:0324/003223.145289:3788268757:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004b0 [2961:2961:0324/003223.145423:3788268890:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1586014730332081298" 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" } } [2961:2961:0324/003223.145488:3788268956:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1586014730332081298" [2961:2961:0324/003223.145539:3788269009:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2961:2961:0324/003223.145596:3788269074:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424 [2961:2961:0324/003223.145663:3788269131:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000007d0 with delay 1200000 [2961:2961:0324/003223.145708:3788269175:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2961:2961:0324/003223.145841:3788269309:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2961:2961:0324/003223.145887:3788269354:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424 [2961:2961:0324/003223.145926:3788269394:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000490 with delay 0 [2961:2961:0324/003223.145986:3788269456: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 [2961:2961:0324/003223.146048:3788269515:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000490 [2961:2961:0324/003223.146135:3788269603:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000003f0 with delay 0 [2961:2961:0324/003223.146189:3788269656:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424 [2961:2961:0324/003223.146234:3788269704:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000007e0 with delay 10000 [2961:2961:0324/003223.146284:3788269751:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000003f0 [2961:2961:0324/003223.146321:3788269788:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2961:2961:0324/003223.146382:3788269849:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.146433:3788269904:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000003f0 with delay 0 [2961:2961:0324/003223.146477:3788269944:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000003f0 [2961:2961:0324/003223.146580:3788270047: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" } } [2961:2961:0324/003223.146872:3788270342:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7010000007e0 [2961:2961:0324/003223.147927:3788271397: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 [2961:2961:0324/003223.148585:3788272055:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000640 with delay 0 [2961:2961:0324/003223.148658:3788272126:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2961:2961:0324/003223.148887:3788272355:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 0 [2961:2961:0324/003223.148931:3788272399:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000640 [2961:2961:0324/003223.148976:3788272443:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000510 [2961:2961:0324/003223.149050:3788272517:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2961:2961:0324/003223.149117:3788272599:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000490 with delay 0 [2961:2961:0324/003223.149182:3788272649:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000490 [2961:2961:0324/003223.149225:3788272694:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2961:2961:0324/003223.149267:3788272735:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 0 [2961:2961:0324/003223.149309:3788272776:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000510 [2961:2961:0324/003223.149345:3788272813:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2961:2961:0324/003223.149390:3788272857:INFO:recurring-task.cc(55)] [Startup] Scheduling 2792 with a delay 0, Now = 210919424 [2961:2961:0324/003223.149429:3788272896:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000490 with delay 0 [2961:2961:0324/003223.149472:3788272940:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000490 [2961:2961:0324/003223.149554:3788273021:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "8673783965484074089" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2961:2961:0324/003223.149598:3788273068:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 3464 with a delay 500000, Now = 210919424 [2961:2961:0324/003223.149639:3788273107:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 500 [2961:2961:0324/003223.149681:3788273148:INFO:recurring-task.cc(55)] [Retry] Scheduling 2792 with a delay 60000000, Now = 210919424 [2961:2961:0324/003223.149721:3788273188:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000460 with delay 60000 [2961:2961:0324/003223.149772:3788273239:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000510 [2961:2961:0324/003223.149812:3788273280:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.149863:3788273330:INFO:invalidation-client-core.cc(488)] Return client token = "" [2961:2961:0324/003223.150003:3788273474: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: "8673783965484074089" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2961:2961:0324/003223.150155:3788273624:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000510 with delay 0 [2961:2961:0324/003223.150205:3788273673:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000510 [2961:2961:0324/003223.150333:3788273801:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "8673783965484074089" 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" } } [2961:2961:0324/003223.150394:3788273862:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "8673783965484074089" [2961:2961:0324/003223.150439:3788273906:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2961:2961:0324/003223.150485:3788273952:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424 [2961:2961:0324/003223.150535:3788274003:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000003f0 with delay 1200000 [2961:2961:0324/003223.150581:3788274049:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2961:2961:0324/003223.150710:3788274177:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2961:2961:0324/003223.150764:3788274232:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424 [2961:2961:0324/003223.150807:3788274275:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000490 with delay 0 [2961:2961:0324/003223.150868:3788274335: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 [2961:2961:0324/003223.150919:3788274386:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000490 [2961:2961:0324/003223.150992:3788274460:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004b0 with delay 0 [2961:2961:0324/003223.151047:3788274514:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424 [2961:2961:0324/003223.151093:3788274563:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000640 with delay 10000 [2961:2961:0324/003223.151153:3788274621:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004b0 [2961:2961:0324/003223.151191:3788274661:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2961:2961:0324/003223.151478:3788274946:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000640 [2961:2961:0324/003223.152724:3788276191:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000460 [2961:2961:0324/003223.179419:3788302890:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x7010000003f0 [2961:2961:0324/003223.179525:3788302993:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2961:2961:0324/003223.179597:3788303065:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2961:2961:0324/003223.179645:3788303112:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [2961:2961:0324/003223.179860:3788303328: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 } [2961:2961:0324/003223.179924:3788303392:INFO:recurring-task.cc(55)] [Send-info] Scheduling 3464 with a delay 500000, Now = 1411419424 [2961:2961:0324/003223.179968:3788303436:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000460 with delay 500 [2961:2961:0324/003223.180025:3788303493:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424 [2961:2961:0324/003223.180068:3788303536:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000640 with delay 1200000 [2961:2961:0324/003223.180131:3788303599:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x701000000460 [2961:2961:0324/003223.180174:3788303643:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.180254:3788303721:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2961:2961:0324/003223.180294:3788303761:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2961:2961:0324/003223.180543:3788304025:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 778801000 max_known_server_time_ms: 314159265 message_id: "2" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "InvClientTest" } performance_counter: { name: "SentMessageType.INITIALIZE" value: 1 } performance_counter: { name: "SentMessageType.TOTAL" value: 1 } performance_counter: { name: "ReceivedMessageType.TOKEN_CONTROL" value: 1 } performance_counter: { name: "ReceivedMessageType.TOTAL" value: 1 } performance_counter: { name: "ListenerEventType.REISSUE_REGISTRATIONS" value: 1 } performance_counter: { name: "ClientErrorType.PERSISTENT_READ_FAILURE" value: 1 } server_registration_summary_requested: false } } [ OK ] InvalidationClientImplTest.Heartbeats (34 ms) [20/28] InvalidationClientImplTest.Heartbeats (34 ms) [ RUN ] ProtocolHandlerTest.TokenMissing [2966:2966:0324/003223.147024:3788270537:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000520 with delay 0 [2966:2966:0324/003223.147164:3788270636:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000520 [2966:2966:0324/003223.147540:3788271009: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 } [2966:2966:0324/003223.147618:3788271086:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2120 with a delay 500000, Now = 210919424 [2966:2966:0324/003223.147679:3788271147:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000540 with delay 500 [2966:2966:0324/003223.147734:3788271201:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000540 [2966:2966:0324/003223.147835:3788271303:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [2966:2966:0324/003223.147882:3788271354:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (4 ms) [21/28] ProtocolHandlerTest.TokenMissing (4 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [2966:2966:0324/003223.148436:3788271910:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000540 with delay 0 [2966:2966:0324/003223.148496:3788271964:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000540 [2966:2966:0324/003223.148595:3788272067:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 2408 with a delay 500000, Now = 210919424 [2966:2966:0324/003223.148655:3788272130:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000520 with delay 500 [2966:2966:0324/003223.148725:3788272194:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000520 [2966:2966:0324/003223.148867:3788272340:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [2966:2966:0324/003223.148965:3788272435: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 } [2966:2966:0324/003223.149039:3788272509: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 } } [2966:2966:0324/003223.149224:3788272693: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 } } } [2966:2966:0324/003223.149396:3788272868: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 [2966:2966:0324/003223.149918:3788273386:INFO:protocol-handler.cc(139)] Incoming message: { } [2966:2966:0324/003223.149973:3788273443:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [2966:2966:0324/003223.150025:3788273500:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [23/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [ RUN ] RecurringTaskTest.PeriodicTask [2966:2966:0324/003223.150367:3788273841:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -964873096 with a delay 10000, Now = 0 [2966:2966:0324/003223.150428:3788273898:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000000390 with delay 10 [2966:2966:0324/003223.150490:3788273957:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000000390 [2966:2966:0324/003223.150546:3788274017:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [2966:2966:0324/003223.150609:3788274080:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 10000 [2966:2966:0324/003223.150661:3788274131:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000003a0 with delay 60 [2966:2966:0324/003223.150718:3788274185:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x7010000003a0 [2966:2966:0324/003223.150757:3788274226:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [2966:2966:0324/003223.150795:3788274263:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 70000 [2966:2966:0324/003223.150833:3788274301:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x701000000390 with delay 60 [2966:2966:0324/003223.150872:3788274339:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x701000000390 [2966:2966:0324/003223.150914:3788274382:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [2966:2966:0324/003223.150951:3788274418:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 130000 [2966:2966:0324/003223.150989:3788274456:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x7010000003a0 with delay 60 [2966:2966:0324/003223.151028:3788274495:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x7010000003a0 [2966:2966:0324/003223.151065:3788274532:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [2966:2966:0324/003223.151104:3788274570:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 190000 [2966:2966:0324/003223.151151:3788274618:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x701000000390 with delay 60 [2966:2966:0324/003223.151189:3788274662:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x701000000390 [2966:2966:0324/003223.151232:3788274699:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [2966:2966:0324/003223.151266:3788274733:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 250000 [2966:2966:0324/003223.151301:3788274768:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x7010000003a0 with delay 60 [2966:2966:0324/003223.151337:3788274804:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x7010000003a0 [2966:2966:0324/003223.151377:3788274846:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [2966:2966:0324/003223.151414:3788274880:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 310000 [2966:2966:0324/003223.151448:3788274915:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x701000000390 with delay 60 [2966:2966:0324/003223.151484:3788274951:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x701000000390 [2966:2966:0324/003223.151518:3788274985:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [2966:2966:0324/003223.151551:3788275018:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873096 with a delay 60000, Now = 370000 [2966:2966:0324/003223.151597:3788275064:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x7010000003a0 with delay 60 [2966:2966:0324/003223.151637:3788275105:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x7010000003a0 [2966:2966:0324/003223.151678:3788275152:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (2 ms) [24/28] RecurringTaskTest.PeriodicTask (2 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [2966:2966:0324/003223.153052:3788276520:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -964873280 with a delay 10000, Now = 0 [2966:2966:0324/003223.153109:3788276588:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000003a0 with delay 10 [2966:2966:0324/003223.153172:3788276640:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000003a0 [2966:2966:0324/003223.153211:3788276678:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [2966:2966:0324/003223.153249:3788276716:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 50000, Now = 10000 [2966:2966:0324/003223.153310:3788276778:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000000390 with delay 50 [2966:2966:0324/003223.153364:3788276831:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x701000000390 [2966:2966:0324/003223.153404:3788276871:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [2966:2966:0324/003223.153443:3788276910:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 149000, Now = 60000 [2966:2966:0324/003223.153486:3788276956:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x7010000003a0 with delay 149 [2966:2966:0324/003223.153535:3788277002:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x7010000003a0 [2966:2966:0324/003223.153595:3788277063:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [2966:2966:0324/003223.153635:3788277102:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 248000, Now = 210000 [2966:2966:0324/003223.153692:3788277159:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x701000000390 with delay 248 [2966:2966:0324/003223.153747:3788277214:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x701000000390 [2966:2966:0324/003223.153791:3788277259:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [2966:2966:0324/003223.153842:3788277314:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 446000, Now = 460000 [2966:2966:0324/003223.153893:3788277361:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x7010000003a0 with delay 446 [2966:2966:0324/003223.153948:3788277417:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x7010000003a0 [2966:2966:0324/003223.153993:3788277460:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [2966:2966:0324/003223.154031:3788277498:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 842000, Now = 910000 [2966:2966:0324/003223.154078:3788277550:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x701000000390 with delay 842 [2966:2966:0324/003223.154163:3788277631:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x701000000390 [2966:2966:0324/003223.154203:3788277670:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [2966:2966:0324/003223.154238:3788277705:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 1040000, Now = 1760000 [2966:2966:0324/003223.154273:3788277740:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x7010000003a0 with delay 1040 [2966:2966:0324/003223.154335:3788277802:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x7010000003a0 [2966:2966:0324/003223.154369:3788277836:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [2966:2966:0324/003223.154403:3788277870:INFO:recurring-task.cc(55)] [Retry] Scheduling -964873280 with a delay 1040000, Now = 2800000 [2966:2966:0324/003223.154438:3788277904:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x701000000390 with delay 1040 [2966:2966:0324/003223.154504:3788277971:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x701000000390 [2966:2966:0324/003223.154538:3788278005:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms) [25/28] RecurringTaskTest.ExponentialBackoffTask (3 ms) [ RUN ] RecurringTaskTest.OneShotTask [2966:2966:0324/003223.155886:3788279354:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -964873240 with a delay 10000, Now = 0 [2966:2966:0324/003223.155937:3788279407:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x701000000390 with delay 10 [2966:2966:0324/003223.155991:3788279458:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x701000000390 [2966:2966:0324/003223.156028:3788279496:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [2966:2966:0324/003223.156081:3788279552:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -964873240 with a delay 10000, Now = 10000 [2966:2966:0324/003223.156153:3788279626:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000000390 with delay 10 [2966:2966:0324/003223.156205:3788279673:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x701000000390 [2966:2966:0324/003223.156245:3788279713:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (2 ms) [26/28] RecurringTaskTest.OneShotTask (2 ms) [ RUN ] ThrottleTest.ThrottlingScripted [2966:2966:0324/003223.157642:3788281111:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x701000000390 with delay 920 [2966:2966:0324/003223.157722:3788281194:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x701000000390 [2966:2966:0324/003223.158106:3788281582:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x701000000390 with delay 45000 [2966:2966:0324/003223.159252:3788282722:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x701000000390 [ OK ] ThrottleTest.ThrottlingScripted (2 ms) [27/28] ThrottleTest.ThrottlingScripted (2 ms) [ RUN ] ThrottleTest.ThrottlingStorm [2966:2966:0324/003223.159429:3788282899:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x701000000390 with delay 990 [2966:2966:0324/003223.159524:3788282992:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x701000000390 [2966:2966:0324/003223.159572:3788283046:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.159647:3788283114:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x701000000390 [2966:2966:0324/003223.159685:3788283151:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.159749:3788283216:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x701000000390 [2966:2966:0324/003223.159786:3788283252:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.159850:3788283316:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x701000000390 [2966:2966:0324/003223.159886:3788283352:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.159950:3788283416:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x701000000390 [2966:2966:0324/003223.159986:3788283452:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.160050:3788283516:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x701000000390 [2966:2966:0324/003223.160088:3788283557:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x7010000003a0 with delay 54000 [2966:2966:0324/003223.161840:3788285308:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000003a0 [2966:2966:0324/003223.161887:3788285353:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x7010000003a0 with delay 1000 [2966:2966:0324/003223.161959:3788285426:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x7010000003a0 [2966:2966:0324/003223.161997:3788285463:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x7010000003a0 with delay 1000 [2966:2966:0324/003223.162061:3788285527:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x7010000003a0 [2966:2966:0324/003223.162100:3788285567:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x7010000003a0 with delay 1000 [2966:2966:0324/003223.162180:3788285647:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x7010000003a0 [2966:2966:0324/003223.162218:3788285685:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x7010000003a0 with delay 1000 [2966:2966:0324/003223.162282:3788285748:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x7010000003a0 [2966:2966:0324/003223.162318:3788285784:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x7010000003a0 with delay 1000 [2966:2966:0324/003223.162388:3788285855:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x7010000003a0 [2966:2966:0324/003223.162426:3788285892:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x7010000003a0 with delay 1000 [2966:2966:0324/003223.162491:3788285957:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x7010000003a0 [2966:2966:0324/003223.162530:3788285998:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x701000000390 with delay 54000 [2966:2966:0324/003223.164229:3788287696:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x701000000390 [2966:2966:0324/003223.164269:3788287736:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.164334:3788287800:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x701000000390 [2966:2966:0324/003223.164371:3788287837:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.164435:3788287902:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x701000000390 [2966:2966:0324/003223.164472:3788287938:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.164536:3788288014:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x701000000390 [2966:2966:0324/003223.164594:3788288062:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.164661:3788288128:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x701000000390 [2966:2966:0324/003223.164698:3788288164:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.164762:3788288228:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x701000000390 [2966:2966:0324/003223.164798:3788288264:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.164862:3788288328:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x701000000390 [2966:2966:0324/003223.164897:3788288364:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x7010000003a0 with delay 54000 [2966:2966:0324/003223.166607:3788290074:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x7010000003a0 [2966:2966:0324/003223.166647:3788290114:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x7010000003a0 with delay 1000 [2966:2966:0324/003223.166713:3788290179:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x7010000003a0 [2966:2966:0324/003223.166749:3788290215:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x7010000003a0 with delay 1000 [2966:2966:0324/003223.166818:3788290288:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x7010000003a0 [2966:2966:0324/003223.166859:3788290325:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x7010000003a0 with delay 1000 [2966:2966:0324/003223.166929:3788290396:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x7010000003a0 [2966:2966:0324/003223.166966:3788290433:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x7010000003a0 with delay 1000 [2966:2966:0324/003223.167031:3788290497:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x7010000003a0 [2966:2966:0324/003223.167067:3788290533:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x7010000003a0 with delay 1000 [2966:2966:0324/003223.167143:3788290610:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x7010000003a0 [2966:2966:0324/003223.167182:3788290649:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x7010000003a0 with delay 1000 [2966:2966:0324/003223.167247:3788290713:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x7010000003a0 [2966:2966:0324/003223.167282:3788290749:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x701000000390 with delay 54000 [2966:2966:0324/003223.168999:3788292466:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x701000000390 [2966:2966:0324/003223.169042:3788292508:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.169110:3788292585:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x701000000390 [2966:2966:0324/003223.169166:3788292633:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.169232:3788292698:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x701000000390 [2966:2966:0324/003223.169268:3788292735:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.169333:3788292799:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x701000000390 [2966:2966:0324/003223.169368:3788292835:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.169432:3788292899:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x701000000390 [2966:2966:0324/003223.169468:3788292935:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.169532:3788292998:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x701000000390 [2966:2966:0324/003223.169568:3788293034:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x701000000390 with delay 1000 [2966:2966:0324/003223.169638:3788293105:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x701000000390 [2966:2966:0324/003223.169674:3788293141:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x7010000003a0 with delay 54000 [2966:2966:0324/003223.171394:3788294861:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x7010000003a0 [ OK ] ThrottleTest.ThrottlingStorm (12 ms) [28/28] ThrottleTest.ThrottlingStorm (12 ms) SUCCESS: all tests passed. Tests took 0 seconds. 2019-03-24 11:12:36,721 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmp7iRsPE/43c9b6eda3d20c10'] 2019-03-24 11:12:36,722 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmp7iRsPE/43c9b6eda3d20c10/output.json'] 2019-03-24 11:12:36,722 - root: [INFO] merge_cmd: /b/swarming/w/ir/cache/vpython/ba947a/bin/python /b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --build-properties {"bot_id": "swarm2374-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553450761559711, "id": "8918082530205608160", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ChromiumOS MSan Tests/11978", "builder:Linux ChromiumOS MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/d488b3fa47490675ada321f1c0c9752db0f8dc9d", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ChromiumOS MSan Builder", "parent_buildnumber:12148", "scheduler_invocation_id:9083512592302289696", "scheduler_job_id:chromium/Linux ChromiumOS MSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ChromiumOS MSan Tests", "buildnumber": 11978, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "got_revision_cp": "refs/heads/master@{#643730}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.memory", "parent_buildername": "Linux ChromiumOS MSan Builder", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "parent_got_revision_cp": "refs/heads/master@{#643730}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "swarm_hashes": {"accessibility_unittests": "7bd012a6b2906b06ca8b8c950272da4e45dd6d20", "angle_unittests": "c52c3cc0f53c82f8f324c1056570d3818b553800", "app_list_unittests": "70598b0feef9a161da9d9aa9ffec4e83c6e64cc3", "app_shell_unittests": "c29cef573baefd0cd1a6a84f7ca22a3635383a68", "ash_unittests": "db38bd4ccb4c90f0dc6526448f192722bb14430d", "aura_unittests": "dc6c4a7818fe1bacef1720b6114e077e63c17cf8", "base_unittests": "25b137184b42cccbd8a4a12cee2ab9838040c1d3", "blink_common_unittests": "b5579db7de32fe0e39f708506a196b38ae75b838", "blink_fuzzer_unittests": "aea31de8ad3f6b93e45ec48056bf3ca1e8d7c8aa", "blink_heap_unittests": "f49da26f9220686bcc86a8f340806da4ef97e4c0", "blink_platform_unittests": "743256452f43cfb4a96d4d39974b7d291e7244f6", "blink_unittests": "43065f2168809b2eb5e53fc1694bdcf7d3ebd336", "boringssl_crypto_tests": "a67e6f077ae1a403c199ad7ba0ce318e6841327d", "boringssl_ssl_tests": "bc9e48bf93d75c7c0f59ee86ed70ce8f8f43cb7f", "browser_tests": "448f64dc2d342ae3c8df68718e21c65514afdccc", "cacheinvalidation_unittests": "dfdb629dadbcb4a99caf2a4daed54eba122268f7", "capture_unittests": "33dc549ce15dab92cc6b82b1ca602b0b68e624f8", "cast_unittests": "8dedc1bb4b36a626f2736b41ecb772ecdcd8b6a5", "cc_unittests": "198ec8c3ad361e62b3158acb41af3d4833974003", "chrome_app_unittests": "93f3753eb005d934c84930b234f720c8fc217861", "chromedriver_unittests": "3001fdfde512b74818341f60d973a16d4712fdd4", "chromeos_components_unittests": "1de7ab88014735f75ea4ea268a1773c75f149769", "chromeos_unittests": "ecf91478d1410713dd621c775b7449c8034c73d5", "components_browsertests": "6f06d3a5760cd74d6948e804bc61cd8d26cf4d1c", "components_unittests": "54bb7eb35a6afae26bd40c998947ae06a0f0ef9b", "compositor_unittests": "2aa5dbe9c9a5968bf5528ab196b6e65938c8b514", "content_browsertests": "2f4a3f063760200b4967cb441212247435561576", "content_unittests": "f96beb1c9c35994d2927acad32c58c7369b151da", "crypto_unittests": "a6ddf4eaf7ca50466a26875e7a3f0495fa9dfea2", "dbus_unittests": "2fb8268a1dc3830411d4a7a8ea25b37a27f7bd6e", "device_unittests": "56f97491be15bab04c4e51e9767805608859421d", "display_unittests": "5a418294e959b97438ac9d699bf4b3955e912218", "events_unittests": "466456b558fb6930abd7ad00905212cc5a29c8da", "exo_unittests": "db9bf4b01aa35c4c7bad5b84979856aa50f67698", "extensions_browsertests": "905c76e10aa44ba3a8fda8e97823bf9ce90889d5", "extensions_unittests": "be017f803d458a82cf08e15592caf563ce4bc52c", "filesystem_service_unittests": "27b38a614055cf400e5e0f846b8e599c3bfc4f72", "gcm_unit_tests": "5afe49a0d35956f27c590c2a9cf15ccf4168d8f8", "gfx_unittests": "4d579d433aa252e5dbdb63755d742d7ec53f1f99", "gin_unittests": "21084b716a0e77bdd4fc5030545ccf5988a1ee40", "google_apis_unittests": "2a227fec92f772906b8ae7130b513b3bb759583f", "gpu_unittests": "7c8ddcb0f714b64ba50dcea15082a41a3f700a2c", "interactive_ui_tests": "f9a68e9a2aa2042a46b7b25993834cc7321889d0", "ipc_tests": "0d31869097083ee8ac3df9cf6a8216015a3ae896", "jingle_unittests": "3abb80ba9024645a161560f430e47ff29c7ef523", "keyboard_unittests": "d879d2e0b2d0565cdcbac5d8df8438762268b6b5", "latency_unittests": "a09289b1de831aea70c5a796d6f95c7f8111bfe6", "leveldb_service_unittests": "929707937a250ba88b0086ac47e23c16fbad11d8", "libjingle_xmpp_unittests": "04838b119bbbf8bfdf651fd593dc8dc2f495f382", "media_blink_unittests": "fce7e34da3e36b6793eff63d400e0ab270fe2fb1", "media_service_unittests": "3522b7e0479a3f8f692831c91995a6628b3b55cf", "media_unittests": "3bcf2acaf3c0059ae1c7a282ac0918b5ba5ceaa4", "message_center_unittests": "c0e0642be5bb58dc8477e393b10e0e67d27ecb04", "midi_unittests": "1865bd29152cd69018b5beb2b96817e1f72292e5", "mojo_core_unittests": "03467e9fb146053f4230db8c828223640205ec0b", "mojo_unittests": "8400a3868e22c9b34ea3c269e6d67632d751939c", "nacl_helper_nonsfi_unittests": "124837afc2e01073806143411b6322253476e616", "nacl_loader_unittests": "1c4bb067510d32b3b472b7df0164807523f367e6", "native_theme_unittests": "7ed036a4e374d8fec59b14e71a26e6b16f20957b", "net_unittests": "b1e13b48ff32b6d851d304f8a83724a34457aa7d", "ozone_gl_unittests": "59f40d8811469830d0a8b2e1809a8b4c36fdf150", "ozone_unittests": "2758a35cf97cf76cc89f44c65db0852758931d48", "ozone_x11_unittests": "e2dec586be4c6b3403abde2bc12dc32dad4f87d9", "pdf_unittests": "f059caa20b364444617e528dc15ebcf7591861ba", "perfetto_unittests": "17a5cc49f77bbbdee208b68a087cac14447fbdeb", "ppapi_unittests": "78d369c71b7715d88cd7c7c6ac2270b30465ed23", "printing_unittests": "d6199581755af61a38cba334f8b79f80a4145a6c", "remoting_unittests": "76b254ab1720ce40a07570535a5f5f96b3cd329c", "sandbox_linux_unittests": "69089b1c2f76c0ac71edd5b2b8bc172139c5b7c7", "service_manager_unittests": "6f9c3c665aa19fcd3df7411377598d7b7f7287e6", "shell_dialogs_unittests": "e372e2de1550b593776684a1d3ea9c039a3de3f1", "skia_unittests": "96ee2efb7fda4f31287ff0b97c09b2cac4226dac", "snapshot_unittests": "eb39a67b5c2a9db82413eb9229f047b24e8eb106", "sql_unittests": "7f200db1a328186c86265d4d8b029456a14f4920", "storage_unittests": "cba10da115880314dd29f862740836f1e4f35647", "sync_integration_tests": "50f102650ceb536d3db7cee0eeb467f709806338", "traffic_annotation_auditor_unittests": "4ae220629e29c83ad4d0756f487bbe3c7f7fcf8a", "ui_base_unittests": "33d70614d899b83aee748ecb78b8fcf1d9d36dd1", "ui_chromeos_unittests": "b108813cca5c2aa0e1c9f4cbd863331688528724", "ui_touch_selection_unittests": "039fb3d8ad6b7510956251d2b8c8569d7b138922", "unit_tests": "cef25e01a8ad5eecdc8fe46a5fbf436c0982249e", "url_unittests": "a876b3066177c6f9aceaca738f2c5b03229feaf8", "usage_time_limit_unittests": "a2f90164b2cc04390954c466ee4a40c27af5327d", "views_unittests": "9b93f91829f8819c000720330c0c78ece43e337d", "viz_unittests": "922ece5d08fe56fd810cf02152dfd93652fc3d98", "wayland_client_perftests": "8c9c98111d05fba2721dc406e44f601ba769b113", "wm_unittests": "acc8dfa3f5a46cfb3ad5e351ba27e9d6cf3c26d3", "wtf_unittests": "523886a3f60b86ee0d8ecc01b46991e443311c53"}} --summary-json /b/swarming/w/ir/tmp/t/tmpCQtprP.json --task-output-dir /b/swarming/w/ir/tmp/t/tmp7iRsPE -o /b/swarming/w/ir/tmp/t/tmpW2Ap0H.json /b/swarming/w/ir/tmp/t/tmp7iRsPE/43c9b6eda3d20c10/output.json Running ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "swarm2374-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553450761559711, "id": "8918082530205608160", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ChromiumOS MSan Tests/11978", "builder:Linux ChromiumOS MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/d488b3fa47490675ada321f1c0c9752db0f8dc9d", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ChromiumOS MSan Builder", "parent_buildnumber:12148", "scheduler_invocation_id:9083512592302289696", "scheduler_job_id:chromium/Linux ChromiumOS MSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ChromiumOS MSan Tests", "buildnumber": 11978, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "got_revision_cp": "refs/heads/master@{#643730}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.memory", "parent_buildername": "Linux ChromiumOS MSan Builder", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "parent_got_revision_cp": "refs/heads/master@{#643730}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "swarm_hashes": {"accessibility_unittests": "7bd012a6b2906b06ca8b8c950272da4e45dd6d20", "angle_unittests": "c52c3cc0f53c82f8f324c1056570d3818b553800", "app_list_unittests": "70598b0feef9a161da9d9aa9ffec4e83c6e64cc3", "app_shell_unittests": "c29cef573baefd0cd1a6a84f7ca22a3635383a68", "ash_unittests": "db38bd4ccb4c90f0dc6526448f192722bb14430d", "aura_unittests": "dc6c4a7818fe1bacef1720b6114e077e63c17cf8", "base_unittests": "25b137184b42cccbd8a4a12cee2ab9838040c1d3", "blink_common_unittests": "b5579db7de32fe0e39f708506a196b38ae75b838", "blink_fuzzer_unittests": "aea31de8ad3f6b93e45ec48056bf3ca1e8d7c8aa", "blink_heap_unittests": "f49da26f9220686bcc86a8f340806da4ef97e4c0", "blink_platform_unittests": "743256452f43cfb4a96d4d39974b7d291e7244f6", "blink_unittests": "43065f2168809b2eb5e53fc1694bdcf7d3ebd336", "boringssl_crypto_tests": "a67e6f077ae1a403c199ad7ba0ce318e6841327d", "boringssl_ssl_tests": "bc9e48bf93d75c7c0f59ee86ed70ce8f8f43cb7f", "browser_tests": "448f64dc2d342ae3c8df68718e21c65514afdccc", "cacheinvalidation_unittests": "dfdb629dadbcb4a99caf2a4daed54eba122268f7", "capture_unittests": "33dc549ce15dab92cc6b82b1ca602b0b68e624f8", "cast_unittests": "8dedc1bb4b36a626f2736b41ecb772ecdcd8b6a5", "cc_unittests": "198ec8c3ad361e62b3158acb41af3d4833974003", "chrome_app_unittests": "93f3753eb005d934c84930b234f720c8fc217861", "chromedriver_unittests": "3001fdfde512b74818341f60d973a16d4712fdd4", "chromeos_components_unittests": "1de7ab88014735f75ea4ea268a1773c75f149769", "chromeos_unittests": "ecf91478d1410713dd621c775b7449c8034c73d5", "components_browsertests": "6f06d3a5760cd74d6948e804bc61cd8d26cf4d1c", "components_unittests": "54bb7eb35a6afae26bd40c998947ae06a0f0ef9b", "compositor_unittests": "2aa5dbe9c9a5968bf5528ab196b6e65938c8b514", "content_browsertests": "2f4a3f063760200b4967cb441212247435561576", "content_unittests": "f96beb1c9c35994d2927acad32c58c7369b151da", "crypto_unittests": "a6ddf4eaf7ca50466a26875e7a3f0495fa9dfea2", "dbus_unittests": "2fb8268a1dc3830411d4a7a8ea25b37a27f7bd6e", "device_unittests": "56f97491be15bab04c4e51e9767805608859421d", "display_unittests": "5a418294e959b97438ac9d699bf4b3955e912218", "events_unittests": "466456b558fb6930abd7ad00905212cc5a29c8da", "exo_unittests": "db9bf4b01aa35c4c7bad5b84979856aa50f67698", "extensions_browsertests": "905c76e10aa44ba3a8fda8e97823bf9ce90889d5", "extensions_unittests": "be017f803d458a82cf08e15592caf563ce4bc52c", "filesystem_service_unittests": "27b38a614055cf400e5e0f846b8e599c3bfc4f72", "gcm_unit_tests": "5afe49a0d35956f27c590c2a9cf15ccf4168d8f8", "gfx_unittests": "4d579d433aa252e5dbdb63755d742d7ec53f1f99", "gin_unittests": "21084b716a0e77bdd4fc5030545ccf5988a1ee40", "google_apis_unittests": "2a227fec92f772906b8ae7130b513b3bb759583f", "gpu_unittests": "7c8ddcb0f714b64ba50dcea15082a41a3f700a2c", "interactive_ui_tests": "f9a68e9a2aa2042a46b7b25993834cc7321889d0", "ipc_tests": "0d31869097083ee8ac3df9cf6a8216015a3ae896", "jingle_unittests": "3abb80ba9024645a161560f430e47ff29c7ef523", "keyboard_unittests": "d879d2e0b2d0565cdcbac5d8df8438762268b6b5", "latency_unittests": "a09289b1de831aea70c5a796d6f95c7f8111bfe6", "leveldb_service_unittests": "929707937a250ba88b0086ac47e23c16fbad11d8", "libjingle_xmpp_unittests": "04838b119bbbf8bfdf651fd593dc8dc2f495f382", "media_blink_unittests": "fce7e34da3e36b6793eff63d400e0ab270fe2fb1", "media_service_unittests": "3522b7e0479a3f8f692831c91995a6628b3b55cf", "media_unittests": "3bcf2acaf3c0059ae1c7a282ac0918b5ba5ceaa4", "message_center_unittests": "c0e0642be5bb58dc8477e393b10e0e67d27ecb04", "midi_unittests": "1865bd29152cd69018b5beb2b96817e1f72292e5", "mojo_core_unittests": "03467e9fb146053f4230db8c828223640205ec0b", "mojo_unittests": "8400a3868e22c9b34ea3c269e6d67632d751939c", "nacl_helper_nonsfi_unittests": "124837afc2e01073806143411b6322253476e616", "nacl_loader_unittests": "1c4bb067510d32b3b472b7df0164807523f367e6", "native_theme_unittests": "7ed036a4e374d8fec59b14e71a26e6b16f20957b", "net_unittests": "b1e13b48ff32b6d851d304f8a83724a34457aa7d", "ozone_gl_unittests": "59f40d8811469830d0a8b2e1809a8b4c36fdf150", "ozone_unittests": "2758a35cf97cf76cc89f44c65db0852758931d48", "ozone_x11_unittests": "e2dec586be4c6b3403abde2bc12dc32dad4f87d9", "pdf_unittests": "f059caa20b364444617e528dc15ebcf7591861ba", "perfetto_unittests": "17a5cc49f77bbbdee208b68a087cac14447fbdeb", "ppapi_unittests": "78d369c71b7715d88cd7c7c6ac2270b30465ed23", "printing_unittests": "d6199581755af61a38cba334f8b79f80a4145a6c", "remoting_unittests": "76b254ab1720ce40a07570535a5f5f96b3cd329c", "sandbox_linux_unittests": "69089b1c2f76c0ac71edd5b2b8bc172139c5b7c7", "service_manager_unittests": "6f9c3c665aa19fcd3df7411377598d7b7f7287e6", "shell_dialogs_unittests": "e372e2de1550b593776684a1d3ea9c039a3de3f1", "skia_unittests": "96ee2efb7fda4f31287ff0b97c09b2cac4226dac", "snapshot_unittests": "eb39a67b5c2a9db82413eb9229f047b24e8eb106", "sql_unittests": "7f200db1a328186c86265d4d8b029456a14f4920", "storage_unittests": "cba10da115880314dd29f862740836f1e4f35647", "sync_integration_tests": "50f102650ceb536d3db7cee0eeb467f709806338", "traffic_annotation_auditor_unittests": "4ae220629e29c83ad4d0756f487bbe3c7f7fcf8a", "ui_base_unittests": "33d70614d899b83aee748ecb78b8fcf1d9d36dd1", "ui_chromeos_unittests": "b108813cca5c2aa0e1c9f4cbd863331688528724", "ui_touch_selection_unittests": "039fb3d8ad6b7510956251d2b8c8569d7b138922", "unit_tests": "cef25e01a8ad5eecdc8fe46a5fbf436c0982249e", "url_unittests": "a876b3066177c6f9aceaca738f2c5b03229feaf8", "usage_time_limit_unittests": "a2f90164b2cc04390954c466ee4a40c27af5327d", "views_unittests": "9b93f91829f8819c000720330c0c78ece43e337d", "viz_unittests": "922ece5d08fe56fd810cf02152dfd93652fc3d98", "wayland_client_perftests": "8c9c98111d05fba2721dc406e44f601ba769b113", "wm_unittests": "acc8dfa3f5a46cfb3ad5e351ba27e9d6cf3c26d3", "wtf_unittests": "523886a3f60b86ee0d8ecc01b46991e443311c53"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpCQtprP.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmp7iRsPE', '-o', '/b/swarming/w/ir/tmp/t/tmpW2Ap0H.json', '/b/swarming/w/ir/tmp/t/tmp7iRsPE/43c9b6eda3d20c10/output.json'] in None (env: None) Command ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "swarm2374-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1553450761559711, "id": "8918082530205608160", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ChromiumOS MSan Tests/11978", "builder:Linux ChromiumOS MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/d488b3fa47490675ada321f1c0c9752db0f8dc9d", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ChromiumOS MSan Builder", "parent_buildnumber:12148", "scheduler_invocation_id:9083512592302289696", "scheduler_job_id:chromium/Linux ChromiumOS MSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ChromiumOS MSan Tests", "buildnumber": 11978, "got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "got_revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "got_revision_cp": "refs/heads/master@{#643730}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "got_webrtc_revision_cp": "refs/heads/master@{#27257}", "mastername": "chromium.memory", "parent_buildername": "Linux ChromiumOS MSan Builder", "parent_got_angle_revision": "eae464dd3092c1c09c4dc4d51a0f50ac5d007722", "parent_got_dawn_revision": "07950e80fe36028ed9cca0a4a99a8b08e9bb4fdf", "parent_got_nacl_revision": "de8da4841bc3d1ed020d798d5a7fd6fb3d817fa1", "parent_got_revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "parent_got_revision_cp": "refs/heads/master@{#643730}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "b346546b7795350b8c910ff06f9520e7f03224f0", "parent_got_v8_revision_cp": "refs/heads/7.5.100@{#1}", "parent_got_webrtc_revision": "85a4a93e77b163098e91f41d8e7415181f23d02c", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27257}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "d488b3fa47490675ada321f1c0c9752db0f8dc9d", "swarm_hashes": {"accessibility_unittests": "7bd012a6b2906b06ca8b8c950272da4e45dd6d20", "angle_unittests": "c52c3cc0f53c82f8f324c1056570d3818b553800", "app_list_unittests": "70598b0feef9a161da9d9aa9ffec4e83c6e64cc3", "app_shell_unittests": "c29cef573baefd0cd1a6a84f7ca22a3635383a68", "ash_unittests": "db38bd4ccb4c90f0dc6526448f192722bb14430d", "aura_unittests": "dc6c4a7818fe1bacef1720b6114e077e63c17cf8", "base_unittests": "25b137184b42cccbd8a4a12cee2ab9838040c1d3", "blink_common_unittests": "b5579db7de32fe0e39f708506a196b38ae75b838", "blink_fuzzer_unittests": "aea31de8ad3f6b93e45ec48056bf3ca1e8d7c8aa", "blink_heap_unittests": "f49da26f9220686bcc86a8f340806da4ef97e4c0", "blink_platform_unittests": "743256452f43cfb4a96d4d39974b7d291e7244f6", "blink_unittests": "43065f2168809b2eb5e53fc1694bdcf7d3ebd336", "boringssl_crypto_tests": "a67e6f077ae1a403c199ad7ba0ce318e6841327d", "boringssl_ssl_tests": "bc9e48bf93d75c7c0f59ee86ed70ce8f8f43cb7f", "browser_tests": "448f64dc2d342ae3c8df68718e21c65514afdccc", "cacheinvalidation_unittests": "dfdb629dadbcb4a99caf2a4daed54eba122268f7", "capture_unittests": "33dc549ce15dab92cc6b82b1ca602b0b68e624f8", "cast_unittests": "8dedc1bb4b36a626f2736b41ecb772ecdcd8b6a5", "cc_unittests": "198ec8c3ad361e62b3158acb41af3d4833974003", "chrome_app_unittests": "93f3753eb005d934c84930b234f720c8fc217861", "chromedriver_unittests": "3001fdfde512b74818341f60d973a16d4712fdd4", "chromeos_components_unittests": "1de7ab88014735f75ea4ea268a1773c75f149769", "chromeos_unittests": "ecf91478d1410713dd621c775b7449c8034c73d5", "components_browsertests": "6f06d3a5760cd74d6948e804bc61cd8d26cf4d1c", "components_unittests": "54bb7eb35a6afae26bd40c998947ae06a0f0ef9b", "compositor_unittests": "2aa5dbe9c9a5968bf5528ab196b6e65938c8b514", "content_browsertests": "2f4a3f063760200b4967cb441212247435561576", "content_unittests": "f96beb1c9c35994d2927acad32c58c7369b151da", "crypto_unittests": "a6ddf4eaf7ca50466a26875e7a3f0495fa9dfea2", "dbus_unittests": "2fb8268a1dc3830411d4a7a8ea25b37a27f7bd6e", "device_unittests": "56f97491be15bab04c4e51e9767805608859421d", "display_unittests": "5a418294e959b97438ac9d699bf4b3955e912218", "events_unittests": "466456b558fb6930abd7ad00905212cc5a29c8da", "exo_unittests": "db9bf4b01aa35c4c7bad5b84979856aa50f67698", "extensions_browsertests": "905c76e10aa44ba3a8fda8e97823bf9ce90889d5", "extensions_unittests": "be017f803d458a82cf08e15592caf563ce4bc52c", "filesystem_service_unittests": "27b38a614055cf400e5e0f846b8e599c3bfc4f72", "gcm_unit_tests": "5afe49a0d35956f27c590c2a9cf15ccf4168d8f8", "gfx_unittests": "4d579d433aa252e5dbdb63755d742d7ec53f1f99", "gin_unittests": "21084b716a0e77bdd4fc5030545ccf5988a1ee40", "google_apis_unittests": "2a227fec92f772906b8ae7130b513b3bb759583f", "gpu_unittests": "7c8ddcb0f714b64ba50dcea15082a41a3f700a2c", "interactive_ui_tests": "f9a68e9a2aa2042a46b7b25993834cc7321889d0", "ipc_tests": "0d31869097083ee8ac3df9cf6a8216015a3ae896", "jingle_unittests": "3abb80ba9024645a161560f430e47ff29c7ef523", "keyboard_unittests": "d879d2e0b2d0565cdcbac5d8df8438762268b6b5", "latency_unittests": "a09289b1de831aea70c5a796d6f95c7f8111bfe6", "leveldb_service_unittests": "929707937a250ba88b0086ac47e23c16fbad11d8", "libjingle_xmpp_unittests": "04838b119bbbf8bfdf651fd593dc8dc2f495f382", "media_blink_unittests": "fce7e34da3e36b6793eff63d400e0ab270fe2fb1", "media_service_unittests": "3522b7e0479a3f8f692831c91995a6628b3b55cf", "media_unittests": "3bcf2acaf3c0059ae1c7a282ac0918b5ba5ceaa4", "message_center_unittests": "c0e0642be5bb58dc8477e393b10e0e67d27ecb04", "midi_unittests": "1865bd29152cd69018b5beb2b96817e1f72292e5", "mojo_core_unittests": "03467e9fb146053f4230db8c828223640205ec0b", "mojo_unittests": "8400a3868e22c9b34ea3c269e6d67632d751939c", "nacl_helper_nonsfi_unittests": "124837afc2e01073806143411b6322253476e616", "nacl_loader_unittests": "1c4bb067510d32b3b472b7df0164807523f367e6", "native_theme_unittests": "7ed036a4e374d8fec59b14e71a26e6b16f20957b", "net_unittests": "b1e13b48ff32b6d851d304f8a83724a34457aa7d", "ozone_gl_unittests": "59f40d8811469830d0a8b2e1809a8b4c36fdf150", "ozone_unittests": "2758a35cf97cf76cc89f44c65db0852758931d48", "ozone_x11_unittests": "e2dec586be4c6b3403abde2bc12dc32dad4f87d9", "pdf_unittests": "f059caa20b364444617e528dc15ebcf7591861ba", "perfetto_unittests": "17a5cc49f77bbbdee208b68a087cac14447fbdeb", "ppapi_unittests": "78d369c71b7715d88cd7c7c6ac2270b30465ed23", "printing_unittests": "d6199581755af61a38cba334f8b79f80a4145a6c", "remoting_unittests": "76b254ab1720ce40a07570535a5f5f96b3cd329c", "sandbox_linux_unittests": "69089b1c2f76c0ac71edd5b2b8bc172139c5b7c7", "service_manager_unittests": "6f9c3c665aa19fcd3df7411377598d7b7f7287e6", "shell_dialogs_unittests": "e372e2de1550b593776684a1d3ea9c039a3de3f1", "skia_unittests": "96ee2efb7fda4f31287ff0b97c09b2cac4226dac", "snapshot_unittests": "eb39a67b5c2a9db82413eb9229f047b24e8eb106", "sql_unittests": "7f200db1a328186c86265d4d8b029456a14f4920", "storage_unittests": "cba10da115880314dd29f862740836f1e4f35647", "sync_integration_tests": "50f102650ceb536d3db7cee0eeb467f709806338", "traffic_annotation_auditor_unittests": "4ae220629e29c83ad4d0756f487bbe3c7f7fcf8a", "ui_base_unittests": "33d70614d899b83aee748ecb78b8fcf1d9d36dd1", "ui_chromeos_unittests": "b108813cca5c2aa0e1c9f4cbd863331688528724", "ui_touch_selection_unittests": "039fb3d8ad6b7510956251d2b8c8569d7b138922", "unit_tests": "cef25e01a8ad5eecdc8fe46a5fbf436c0982249e", "url_unittests": "a876b3066177c6f9aceaca738f2c5b03229feaf8", "usage_time_limit_unittests": "a2f90164b2cc04390954c466ee4a40c27af5327d", "views_unittests": "9b93f91829f8819c000720330c0c78ece43e337d", "viz_unittests": "922ece5d08fe56fd810cf02152dfd93652fc3d98", "wayland_client_perftests": "8c9c98111d05fba2721dc406e44f601ba769b113", "wm_unittests": "acc8dfa3f5a46cfb3ad5e351ba27e9d6cf3c26d3", "wtf_unittests": "523886a3f60b86ee0d8ecc01b46991e443311c53"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpCQtprP.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmp7iRsPE', '-o', '/b/swarming/w/ir/tmp/t/tmpW2Ap0H.json', '/b/swarming/w/ir/tmp/t/tmp7iRsPE/43c9b6eda3d20c10/output.json'] returned exit code 0