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/tmpbww3bw.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpffYNcU --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/tmpGac9Ckmerge_script_log --merge-additional-args '[]' --build-properties '{"bot_id": "swarm2374-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552918168087415, "id": "8918640994938152752", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ChromiumOS MSan Tests/11867", "builder:Linux ChromiumOS MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/532a82810a40d3bbdbe66eafc6de66ec01252210", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ChromiumOS MSan Builder", "parent_buildnumber:12036", "scheduler_invocation_id:9084071057514182576", "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": 11867, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "991ab98f113f5f51ec87d767b45523b19cd15b9e", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "got_revision_cp": "refs/heads/master@{#641568}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "got_webrtc_revision": "df644be3536b61256ab9e22bb0891a8b6a1d01c2", "got_webrtc_revision_cp": "refs/heads/master@{#27155}", "mastername": "chromium.memory", "parent_buildername": "Linux ChromiumOS MSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "991ab98f113f5f51ec87d767b45523b19cd15b9e", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "parent_got_revision_cp": "refs/heads/master@{#641568}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "parent_got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "parent_got_webrtc_revision": "df644be3536b61256ab9e22bb0891a8b6a1d01c2", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27155}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "swarm_hashes": {"accessibility_unittests": "77657a56215abce527f179cee0b495540928de3c", "angle_unittests": "b70d85c9f3906f94924eb11e9d5b122cab28d065", "app_list_unittests": "35164ac5e91cd2b46f73d4ba283d5c84914334bc", "app_shell_unittests": "bf5d079a569b62e3a5fe40faaa54ce7be94804d2", "ash_unittests": "92e721e6e6dc9a022238e9af36714397aaecfda6", "aura_unittests": "e7830d3a8705864888ad19b3bbc249aac7973950", "base_unittests": "0f9cb3c1577a282cc56e069a09eaa43185b710ef", "blink_common_unittests": "7117068b032ea3df34fbdc432a4fef66bc8f1a26", "blink_fuzzer_unittests": "7659fef36aa2db42cdfedf8a5d58dcbad19a9f14", "blink_heap_unittests": "688ab4072e0d5c14218d893d71ff8d01f41d71ba", "blink_platform_unittests": "df2391e47f99216ba7179ede45f711dca1968231", "blink_unittests": "b0c9e25c3d60d64eb6dde3972ca9de338f76325b", "boringssl_crypto_tests": "8ed296da9458a249b233d884ec7a2c74fbe56c3b", "boringssl_ssl_tests": "a4326eec2bbc8835563d6bb4abe7fee2aaf43007", "browser_tests": "99727d3cee82fcfd1927e15e93eb88ba343f1609", "cacheinvalidation_unittests": "26eb11a34f57da9a2abf246039845ba8f72fdd47", "capture_unittests": "bffb4c1c9c5f890576e6f77d35a45bb637438756", "cast_unittests": "6bd2524dcf68198b1313b394cb3f8f299cc88ce4", "cc_unittests": "9565b45514699c5fc05471a854ea06d31c54173a", "chrome_app_unittests": "5a48a2e30fe958a44a8fa98b0e6b1977c84e7e7f", "chromedriver_unittests": "15fdf9f3c582ed26e8fd30318df3d82459455274", "chromeos_components_unittests": "47a36331945a75c288436520a9bbf452675d7165", "chromeos_unittests": "d45f2b5fb6d312ad99957ebe82bdcc71a44a79fb", "components_browsertests": "66505cd0e83c70434c54bd5d2ac4345cff14c0b2", "components_unittests": "a4de17137c0d9b2a7e2c133835c3ec06a383a054", "compositor_unittests": "6071f780b1e0776b87b9998f5757953f5b124199", "content_browsertests": "9703f6ffc96540eb1d309aea9a43cfed79c1d2ff", "content_unittests": "a19c55902c23646cd1902fb674f36c56b9099a7b", "crypto_unittests": "dc61523e2da78e5e3865f8c03745e26630cfb2de", "dbus_unittests": "7b013593eb0e3f6907797ff355c239fba715709c", "device_unittests": "78da84d8557b2eeed4cebc8f46d6dd89e7ba4a49", "display_unittests": "e7e20dae68e9ffb75e00d239fdaf9b2ec137481c", "events_unittests": "acc9f6c8f34fa796a0766f6267c88ee00d4f71f7", "exo_unittests": "c604ffa0540d8ff736396417b0550aee55483c06", "extensions_browsertests": "8b635d8bf7a5a567c93f7648df25fea89921655a", "extensions_unittests": "c170dec454779ba0e124f56d048e3e7e9283f6f7", "filesystem_service_unittests": "e1746e4927ad2c136033a0f1ac64e4fb3bc0fe03", "gcm_unit_tests": "446264c5193fbc28322314b8be3463d39653c92a", "gfx_unittests": "b0d8752f97bc13bb0f95fde7e65cb59fc5d910ef", "gin_unittests": "af15a210bb7c9153f8464b8029a46b3eb9fcb600", "google_apis_unittests": "90b841b69dbe7d966432a089d7b3627fb54ef078", "gpu_unittests": "009e6220ece2c3f9c043a21d205a4fd60f7268b5", "interactive_ui_tests": "14e5cfd3e71748aa3d5e0d6e8847b165db74893f", "ipc_tests": "c45361febd0e07a60e42aa6c4b7718d2750c9362", "jingle_unittests": "e64947b30eae559fdf3cb4ba1ea12d2a9c22da2e", "keyboard_unittests": "2645c8d6574f077cab7e5c97b0c9b180655d0255", "latency_unittests": "99e3d7098a7f4608f74bfee0056f617250ea095f", "leveldb_service_unittests": "cb8dd4976b4ea9559dbd20cc13792bda0c7299f4", "libjingle_xmpp_unittests": "0200181537eeab3d725bb79beca8b2ce0009c12d", "media_blink_unittests": "3299f8f7b2d8c018b46946e265bbe84778383c71", "media_service_unittests": "546736fe867aada5d9f87d73262b0f0b54313500", "media_unittests": "610c2a0d368840a1f18f81b75ac26759aa7505c1", "message_center_unittests": "de1ca4f9764710310a0b830bb8a4f32ef185fc0f", "midi_unittests": "f39508e7bbfa64eb85dcd5d574eeac09ba3b0e61", "mojo_core_unittests": "de7aaeffadcb1a9c67e2deb5cb5df0a6553ada51", "mojo_unittests": "37680db7fde79a04370e560cf0ecc6172e515f50", "nacl_helper_nonsfi_unittests": "5662230fb325b915ae13bdc32e1e245886751f38", "nacl_loader_unittests": "359fb99e32700baa996f88023774c0a77f41e77b", "native_theme_unittests": "ad74f3ff4657247e2d09d693cef2d00132581dc6", "net_unittests": "6101a7c65994259547f724500701ef44b4219941", "ozone_gl_unittests": "0a26be0d420e99daedcfda726dc58e7dfaf4790f", "ozone_unittests": "87d00bbe11ed1ce6acabbfe29bf27455e90edc6d", "ozone_x11_unittests": "c4642eb7bf276f1f4cad532d706fa68b42889269", "pdf_unittests": "0ce52596a8e994194363b5874cccb39b6a680726", "ppapi_unittests": "4886f144adcc9f64b43ed05517cce63d2023bd4f", "printing_unittests": "1f160dc72793167fe0e6242b2295c960179169e4", "remoting_unittests": "60df526f3b416301d4623b8055b2e807d2caf62b", "sandbox_linux_unittests": "bef5eab721804ec7fd185ef9253fb7e026d45626", "service_manager_unittests": "9409cc2b98aed18f2d44f192acb9b5cb2f180716", "shell_dialogs_unittests": "698aef2d5db64d6bf57fb4d8a4514b1b7d4f0170", "skia_unittests": "a11ae40bab8a2d11dc4c55b21c794364c6c62d44", "snapshot_unittests": "431a7c5a79fd17f81335dd35882e78b8a5d93f2b", "sql_unittests": "643df51f01c4a4daf208dc355a860174693eaec5", "storage_unittests": "cbe22c79d0d7290c822f03ee4dcdda90abff55fd", "sync_integration_tests": "6c9690aa5038db40259d53ab9a9bef18216a5677", "traffic_annotation_auditor_unittests": "9926ad158e1902d58281f6e0c53b8840ed663313", "ui_base_unittests": "f22d951e45ee62e1991de3f38cf6602221ec6e68", "ui_chromeos_unittests": "f31d765397198f6352e73a2dad214a37ff7fc01a", "ui_touch_selection_unittests": "1b19d833968815b61b6048e4c8ff0550795b473b", "unit_tests": "9df90e8a009d7e6f92729f574faa2d037e9a4f8a", "url_unittests": "bfeff0c5df5e3691e816bd8845135615e1a6256b", "usage_time_limit_unittests": "84c89273b65718cb89b124c71c384e6054f3319c", "views_unittests": "174830fe2afb874e36a35084a9a1fceace1b10cc", "viz_unittests": "6cf8d8a6875f95047d9622272f045f149650b7b1", "wayland_client_perftests": "3d9a1916dcd3709612ba7495f069c84cadbd0250", "wm_unittests": "9fd8a71f431d0842327f4168ca2a8220e2c71404", "wtf_unittests": "306fcdd994ab596d998968f109b00602c0cb6618"}}' --summary-json-file /b/swarming/w/ir/tmp/t/tmp0rkFsY.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/tmpDd3UZy.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/tmpbww3bw.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpffYNcU', '--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/tmpGac9Ckmerge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"bot_id": "swarm2374-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552918168087415, "id": "8918640994938152752", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ChromiumOS MSan Tests/11867", "builder:Linux ChromiumOS MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/532a82810a40d3bbdbe66eafc6de66ec01252210", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ChromiumOS MSan Builder", "parent_buildnumber:12036", "scheduler_invocation_id:9084071057514182576", "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": 11867, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "991ab98f113f5f51ec87d767b45523b19cd15b9e", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "got_revision_cp": "refs/heads/master@{#641568}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "got_webrtc_revision": "df644be3536b61256ab9e22bb0891a8b6a1d01c2", "got_webrtc_revision_cp": "refs/heads/master@{#27155}", "mastername": "chromium.memory", "parent_buildername": "Linux ChromiumOS MSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "991ab98f113f5f51ec87d767b45523b19cd15b9e", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "parent_got_revision_cp": "refs/heads/master@{#641568}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "parent_got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "parent_got_webrtc_revision": "df644be3536b61256ab9e22bb0891a8b6a1d01c2", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27155}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "swarm_hashes": {"accessibility_unittests": "77657a56215abce527f179cee0b495540928de3c", "angle_unittests": "b70d85c9f3906f94924eb11e9d5b122cab28d065", "app_list_unittests": "35164ac5e91cd2b46f73d4ba283d5c84914334bc", "app_shell_unittests": "bf5d079a569b62e3a5fe40faaa54ce7be94804d2", "ash_unittests": "92e721e6e6dc9a022238e9af36714397aaecfda6", "aura_unittests": "e7830d3a8705864888ad19b3bbc249aac7973950", "base_unittests": "0f9cb3c1577a282cc56e069a09eaa43185b710ef", "blink_common_unittests": "7117068b032ea3df34fbdc432a4fef66bc8f1a26", "blink_fuzzer_unittests": "7659fef36aa2db42cdfedf8a5d58dcbad19a9f14", "blink_heap_unittests": "688ab4072e0d5c14218d893d71ff8d01f41d71ba", "blink_platform_unittests": "df2391e47f99216ba7179ede45f711dca1968231", "blink_unittests": "b0c9e25c3d60d64eb6dde3972ca9de338f76325b", "boringssl_crypto_tests": "8ed296da9458a249b233d884ec7a2c74fbe56c3b", "boringssl_ssl_tests": "a4326eec2bbc8835563d6bb4abe7fee2aaf43007", "browser_tests": "99727d3cee82fcfd1927e15e93eb88ba343f1609", "cacheinvalidation_unittests": "26eb11a34f57da9a2abf246039845ba8f72fdd47", "capture_unittests": "bffb4c1c9c5f890576e6f77d35a45bb637438756", "cast_unittests": "6bd2524dcf68198b1313b394cb3f8f299cc88ce4", "cc_unittests": "9565b45514699c5fc05471a854ea06d31c54173a", "chrome_app_unittests": "5a48a2e30fe958a44a8fa98b0e6b1977c84e7e7f", "chromedriver_unittests": "15fdf9f3c582ed26e8fd30318df3d82459455274", "chromeos_components_unittests": "47a36331945a75c288436520a9bbf452675d7165", "chromeos_unittests": "d45f2b5fb6d312ad99957ebe82bdcc71a44a79fb", "components_browsertests": "66505cd0e83c70434c54bd5d2ac4345cff14c0b2", "components_unittests": "a4de17137c0d9b2a7e2c133835c3ec06a383a054", "compositor_unittests": "6071f780b1e0776b87b9998f5757953f5b124199", "content_browsertests": "9703f6ffc96540eb1d309aea9a43cfed79c1d2ff", "content_unittests": "a19c55902c23646cd1902fb674f36c56b9099a7b", "crypto_unittests": "dc61523e2da78e5e3865f8c03745e26630cfb2de", "dbus_unittests": "7b013593eb0e3f6907797ff355c239fba715709c", "device_unittests": "78da84d8557b2eeed4cebc8f46d6dd89e7ba4a49", "display_unittests": "e7e20dae68e9ffb75e00d239fdaf9b2ec137481c", "events_unittests": "acc9f6c8f34fa796a0766f6267c88ee00d4f71f7", "exo_unittests": "c604ffa0540d8ff736396417b0550aee55483c06", "extensions_browsertests": "8b635d8bf7a5a567c93f7648df25fea89921655a", "extensions_unittests": "c170dec454779ba0e124f56d048e3e7e9283f6f7", "filesystem_service_unittests": "e1746e4927ad2c136033a0f1ac64e4fb3bc0fe03", "gcm_unit_tests": "446264c5193fbc28322314b8be3463d39653c92a", "gfx_unittests": "b0d8752f97bc13bb0f95fde7e65cb59fc5d910ef", "gin_unittests": "af15a210bb7c9153f8464b8029a46b3eb9fcb600", "google_apis_unittests": "90b841b69dbe7d966432a089d7b3627fb54ef078", "gpu_unittests": "009e6220ece2c3f9c043a21d205a4fd60f7268b5", "interactive_ui_tests": "14e5cfd3e71748aa3d5e0d6e8847b165db74893f", "ipc_tests": "c45361febd0e07a60e42aa6c4b7718d2750c9362", "jingle_unittests": "e64947b30eae559fdf3cb4ba1ea12d2a9c22da2e", "keyboard_unittests": "2645c8d6574f077cab7e5c97b0c9b180655d0255", "latency_unittests": "99e3d7098a7f4608f74bfee0056f617250ea095f", "leveldb_service_unittests": "cb8dd4976b4ea9559dbd20cc13792bda0c7299f4", "libjingle_xmpp_unittests": "0200181537eeab3d725bb79beca8b2ce0009c12d", "media_blink_unittests": "3299f8f7b2d8c018b46946e265bbe84778383c71", "media_service_unittests": "546736fe867aada5d9f87d73262b0f0b54313500", "media_unittests": "610c2a0d368840a1f18f81b75ac26759aa7505c1", "message_center_unittests": "de1ca4f9764710310a0b830bb8a4f32ef185fc0f", "midi_unittests": "f39508e7bbfa64eb85dcd5d574eeac09ba3b0e61", "mojo_core_unittests": "de7aaeffadcb1a9c67e2deb5cb5df0a6553ada51", "mojo_unittests": "37680db7fde79a04370e560cf0ecc6172e515f50", "nacl_helper_nonsfi_unittests": "5662230fb325b915ae13bdc32e1e245886751f38", "nacl_loader_unittests": "359fb99e32700baa996f88023774c0a77f41e77b", "native_theme_unittests": "ad74f3ff4657247e2d09d693cef2d00132581dc6", "net_unittests": "6101a7c65994259547f724500701ef44b4219941", "ozone_gl_unittests": "0a26be0d420e99daedcfda726dc58e7dfaf4790f", "ozone_unittests": "87d00bbe11ed1ce6acabbfe29bf27455e90edc6d", "ozone_x11_unittests": "c4642eb7bf276f1f4cad532d706fa68b42889269", "pdf_unittests": "0ce52596a8e994194363b5874cccb39b6a680726", "ppapi_unittests": "4886f144adcc9f64b43ed05517cce63d2023bd4f", "printing_unittests": "1f160dc72793167fe0e6242b2295c960179169e4", "remoting_unittests": "60df526f3b416301d4623b8055b2e807d2caf62b", "sandbox_linux_unittests": "bef5eab721804ec7fd185ef9253fb7e026d45626", "service_manager_unittests": "9409cc2b98aed18f2d44f192acb9b5cb2f180716", "shell_dialogs_unittests": "698aef2d5db64d6bf57fb4d8a4514b1b7d4f0170", "skia_unittests": "a11ae40bab8a2d11dc4c55b21c794364c6c62d44", "snapshot_unittests": "431a7c5a79fd17f81335dd35882e78b8a5d93f2b", "sql_unittests": "643df51f01c4a4daf208dc355a860174693eaec5", "storage_unittests": "cbe22c79d0d7290c822f03ee4dcdda90abff55fd", "sync_integration_tests": "6c9690aa5038db40259d53ab9a9bef18216a5677", "traffic_annotation_auditor_unittests": "9926ad158e1902d58281f6e0c53b8840ed663313", "ui_base_unittests": "f22d951e45ee62e1991de3f38cf6602221ec6e68", "ui_chromeos_unittests": "f31d765397198f6352e73a2dad214a37ff7fc01a", "ui_touch_selection_unittests": "1b19d833968815b61b6048e4c8ff0550795b473b", "unit_tests": "9df90e8a009d7e6f92729f574faa2d037e9a4f8a", "url_unittests": "bfeff0c5df5e3691e816bd8845135615e1a6256b", "usage_time_limit_unittests": "84c89273b65718cb89b124c71c384e6054f3319c", "views_unittests": "174830fe2afb874e36a35084a9a1fceace1b10cc", "viz_unittests": "6cf8d8a6875f95047d9622272f045f149650b7b1", "wayland_client_perftests": "3d9a1916dcd3709612ba7495f069c84cadbd0250", "wm_unittests": "9fd8a71f431d0842327f4168ca2a8220e2c71404", "wtf_unittests": "306fcdd994ab596d998968f109b00602c0cb6618"}}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmp0rkFsY.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/tmpDd3UZy.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: frozenset([0]) step_test_data: <lambda>(...) trigger_specs: () full environment: ADDRFAM: inet BOTO_CONFIG: /b/swarming/w/ir/tmp/gsutil_task/.boto BUILDBUCKET_EXPERIMENTAL: FALSE CHROME_HEADLESS: 1 CIPD_CACHE_DIR: /b/swarming/cipd_cache/cache CIPD_PROTOCOL: v2 DEVSHELL_CLIENT_PORT: 36929 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/8918640994938152752 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/itqvEn4U/luci_context.690346327 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: 43a9f44d4b319611 TEMP: /b/swarming/w/ir/tmp/t TEMPDIR: /b/swarming/w/ir/tmp/t TERM: linux TMP: /b/swarming/w/ir/tmp/t TMPDIR: /b/swarming/w/ir/tmp/t UPSTART_EVENTS: net-device-up UPSTART_INSTANCE: UPSTART_JOB: chromebuild-startup USER: chrome-bot USERNAME: chrome-bot VPYTHON_VIRTUALENV_ROOT: /b/swarming/w/ir/cache/vpython _: /b/swarming/w/ir/cipd_bin_packages/vpython Set PYTHONPATH: /b/swarming/w/ir/kitchen-checkout/build/scripts:/b/swarming/w/ir/kitchen-checkout/build/site_config:/b/swarming/w/ir/kitchen-checkout/build/third_party:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_8_4p1:/b/swarming/w/ir/kitchen-checkout/build/third_party/buildbot_slave_8_4:/b/swarming/w/ir/kitchen-checkout/build/third_party/coverage-3.7.1:/b/swarming/w/ir/kitchen-checkout/build/third_party/decorator_3_3_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/google_api_python_client:/b/swarming/w/ir/kitchen-checkout/build/third_party/httplib2/python2:/b/swarming/w/ir/kitchen-checkout/build/third_party/infra_libs:/b/swarming/w/ir/kitchen-checkout/build/third_party/jinja2:/b/swarming/w/ir/kitchen-checkout/build/third_party/markupsafe:/b/swarming/w/ir/kitchen-checkout/build/third_party/oauth2client:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1:/b/swarming/w/ir/kitchen-checkout/build/third_party/pyasn1-modules:/b/swarming/w/ir/kitchen-checkout/build/third_party/python-rsa:/b/swarming/w/ir/kitchen-checkout/build/third_party/requests_2_10_0:/b/swarming/w/ir/kitchen-checkout/build/third_party/setuptools-0.6c11:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/sqlalchemy_migrate_0_7_1:/b/swarming/w/ir/kitchen-checkout/build/third_party/tempita_0_5:/b/swarming/w/ir/kitchen-checkout/build/third_party/twisted_10_2:/b/swarming/w/ir/kitchen-checkout/build/third_party/uritemplate:/b/swarming/w/ir/kitchen-checkout/build/third_party/site-packages 2019-03-18 07:19:22,021 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmpffYNcU' 2019-03-18 07:19:22,021 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmpffYNcU' already exists! 2019-03-18 07:19:22,021 - root: [WARNING] task_output_dir existing content: [] 2019-03-18 07:19:22,021 - 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/tmpDd3UZy.json -output-dir /b/swarming/w/ir/tmp/t/tmpffYNcU -task-summary-json /b/swarming/w/ir/tmp/t/tmp0rkFsY.json [D2019-03-18T07:19:22.029533-07:00 15657 0 auth.go:1265] Minting a new token {"key":"luci_ctx/998331306d422ea38711829d83e6a90a44f493edb79ea88e8a9691a6c4f2c19e", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-18T07:19:22.029606-07:00 15657 0 luci_ctx.go:138] POST http://127.0.0.1:35586/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/998331306d422ea38711829d83e6a90a44f493edb79ea88e8a9691a6c4f2c19e", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-18T07:19:22.031492-07:00 15657 0 auth.go:1222] Token expires in 54m56.968533346s {"key":"luci_ctx/998331306d422ea38711829d83e6a90a44f493edb79ea88e8a9691a6c4f2c19e", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 43a9f7dcde48e810: 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/io4pbpnB/output.json IMPORTANT DEBUGGING NOTE: batches of tests are run inside their own process. For debugging a test inside a debugger, use the --gtest_filter=<your_test_name> flag along with --single-process-tests. Using sharding settings from environment. This is shard 0/1 Using 8 parallel jobs. [ RUN ] ProtocolHandlerTest.TokenMissing [20421:20421:0315/223624.590345:7731296563:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000540 with delay 0 [20421:20421:0315/223624.590515:7731296666:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000540 [20421:20421:0315/223624.590930:7731297079: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 } [20421:20421:0315/223624.591000:7731297157:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2120 with a delay 500000, Now = 210919424 [20421:20421:0315/223624.591047:7731297196:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000560 with delay 500 [20421:20421:0315/223624.591101:7731297250:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000560 [20421:20421:0315/223624.591215:7731297364:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [20421:20421:0315/223624.591259:7731297407:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (9 ms) [1/28] ProtocolHandlerTest.TokenMissing (9 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [20421:20421:0315/223624.591884:7731298034:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000560 with delay 0 [20421:20421:0315/223624.591934:7731298084:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000560 [20421:20421:0315/223624.591984:7731298134:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 2408 with a delay 500000, Now = 210919424 [20421:20421:0315/223624.592031:7731298180:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000540 with delay 500 [20421:20421:0315/223624.592085:7731298233:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000540 [20421:20421:0315/223624.592194:7731298342:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [20421:20421:0315/223624.592279:7731298434: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 } [20421:20421:0315/223624.592359:7731298508: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 } } [20421:20421:0315/223624.592506:7731298658: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 } } } [20421:20421:0315/223624.592644:7731298803:ERROR:protocol-handler.cc(323)] Tried to send invalid message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true is_trickle_restart: true } } } [ OK ] ProtocolHandlerTest.InvalidOutboundMessage (1 ms) [2/28] ProtocolHandlerTest.InvalidOutboundMessage (1 ms) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage [20421:20421:0315/223624.593165:7731299326:INFO:protocol-handler.cc(139)] Incoming message: { } [20421:20421:0315/223624.593225:7731299373:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [20421:20421:0315/223624.593267:7731299415:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [3/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [ RUN ] RecurringTaskTest.PeriodicTask [20421:20421:0315/223624.593573:7731299723:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -588068408 with a delay 10000, Now = 0 [20421:20421:0315/223624.593614:7731299765:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000003b0 with delay 10 [20421:20421:0315/223624.593702:7731299851:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000003b0 [20421:20421:0315/223624.593742:7731299895:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [20421:20421:0315/223624.593792:7731299941:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 10000 [20421:20421:0315/223624.593832:7731299980:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000003c0 with delay 60 [20421:20421:0315/223624.593888:7731300035:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x7010000003c0 [20421:20421:0315/223624.593922:7731300069:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [20421:20421:0315/223624.593955:7731300102:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 70000 [20421:20421:0315/223624.593987:7731300134:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7010000003b0 with delay 60 [20421:20421:0315/223624.594027:7731300174:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7010000003b0 [20421:20421:0315/223624.594059:7731300206:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [20421:20421:0315/223624.594091:7731300238:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 130000 [20421:20421:0315/223624.594123:7731300270:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x7010000003c0 with delay 60 [20421:20421:0315/223624.594156:7731300303:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x7010000003c0 [20421:20421:0315/223624.594187:7731300334:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [20421:20421:0315/223624.594219:7731300366:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 190000 [20421:20421:0315/223624.594251:7731300398:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7010000003b0 with delay 60 [20421:20421:0315/223624.594285:7731300432:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7010000003b0 [20421:20421:0315/223624.594316:7731300463:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [20421:20421:0315/223624.594348:7731300495:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 250000 [20421:20421:0315/223624.594380:7731300527:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x7010000003c0 with delay 60 [20421:20421:0315/223624.594413:7731300560:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x7010000003c0 [20421:20421:0315/223624.594444:7731300591:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [20421:20421:0315/223624.594475:7731300622:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 310000 [20421:20421:0315/223624.594507:7731300656:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7010000003b0 with delay 60 [20421:20421:0315/223624.594542:7731300689:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7010000003b0 [20421:20421:0315/223624.594573:7731300720:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [20421:20421:0315/223624.594627:7731300775:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068408 with a delay 60000, Now = 370000 [20421:20421:0315/223624.594668:7731300815:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x7010000003c0 with delay 60 [20421:20421:0315/223624.594705:7731300853:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x7010000003c0 [20421:20421:0315/223624.594740:7731300890:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (2 ms) [4/28] RecurringTaskTest.PeriodicTask (2 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [20421:20421:0315/223624.596017:7731302167:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -588068592 with a delay 10000, Now = 0 [20421:20421:0315/223624.596059:7731302211:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000003c0 with delay 10 [20421:20421:0315/223624.596100:7731302251:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000003c0 [20421:20421:0315/223624.596143:7731302292:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [20421:20421:0315/223624.596188:7731302337:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 50000, Now = 10000 [20421:20421:0315/223624.596231:7731302380:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000003b0 with delay 50 [20421:20421:0315/223624.596272:7731302420:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7010000003b0 [20421:20421:0315/223624.596312:7731302461:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [20421:20421:0315/223624.596349:7731302499:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 149000, Now = 60000 [20421:20421:0315/223624.596386:7731302537:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x7010000003c0 with delay 149 [20421:20421:0315/223624.596429:7731302577:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x7010000003c0 [20421:20421:0315/223624.596467:7731302615:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [20421:20421:0315/223624.596504:7731302655:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 248000, Now = 210000 [20421:20421:0315/223624.596544:7731302692:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7010000003b0 with delay 248 [20421:20421:0315/223624.596622:7731302771:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7010000003b0 [20421:20421:0315/223624.596666:7731302817:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [20421:20421:0315/223624.596704:7731302852:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 446000, Now = 460000 [20421:20421:0315/223624.596741:7731302889:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x7010000003c0 with delay 446 [20421:20421:0315/223624.596790:7731302938:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x7010000003c0 [20421:20421:0315/223624.596826:7731302975:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [20421:20421:0315/223624.596863:7731303011:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 842000, Now = 910000 [20421:20421:0315/223624.596898:7731303073:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7010000003b0 with delay 842 [20421:20421:0315/223624.596980:7731303127:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7010000003b0 [20421:20421:0315/223624.597012:7731303163:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [20421:20421:0315/223624.597049:7731303197:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 1040000, Now = 1760000 [20421:20421:0315/223624.597082:7731303229:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x7010000003c0 with delay 1040 [20421:20421:0315/223624.597137:7731303284:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x7010000003c0 [20421:20421:0315/223624.597169:7731303316:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [20421:20421:0315/223624.597205:7731303353:INFO:recurring-task.cc(55)] [Retry] Scheduling -588068592 with a delay 1040000, Now = 2800000 [20421:20421:0315/223624.597238:7731303385:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7010000003b0 with delay 1040 [20421:20421:0315/223624.597292:7731303440:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7010000003b0 [20421:20421:0315/223624.597324:7731303471:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms) [5/28] RecurringTaskTest.ExponentialBackoffTask (3 ms) [ RUN ] RecurringTaskTest.OneShotTask [20421:20421:0315/223624.598523:7731304673:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -588068552 with a delay 10000, Now = 0 [20421:20421:0315/223624.598563:7731304715:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7010000003b0 with delay 10 [20421:20421:0315/223624.598635:7731304793:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7010000003b0 [20421:20421:0315/223624.598682:7731304838:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [20421:20421:0315/223624.598737:7731304886:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -588068552 with a delay 10000, Now = 10000 [20421:20421:0315/223624.598786:7731304935:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000003b0 with delay 10 [20421:20421:0315/223624.598827:7731304976:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7010000003b0 [20421:20421:0315/223624.598862:7731305012:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (1 ms) [6/28] RecurringTaskTest.OneShotTask (1 ms) [ RUN ] ThrottleTest.ThrottlingScripted [20421:20421:0315/223624.600172:7731306321:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7010000003b0 with delay 920 [20421:20421:0315/223624.600237:7731306385:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000003b0 [20421:20421:0315/223624.600583:7731306731:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7010000003b0 with delay 45000 [20421:20421:0315/223624.601657:7731307805:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000003b0 [ OK ] ThrottleTest.ThrottlingScripted (1 ms) [7/28] ThrottleTest.ThrottlingScripted (1 ms) [ RUN ] ThrottleTest.ThrottlingStorm [20421:20421:0315/223624.601849:7731307999:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7010000003b0 with delay 990 [20421:20421:0315/223624.601942:7731308090:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7010000003b0 [20421:20421:0315/223624.601982:7731308129:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.602047:7731308194:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7010000003b0 [20421:20421:0315/223624.602081:7731308228:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.602140:7731308286:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7010000003b0 [20421:20421:0315/223624.602173:7731308320:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.602232:7731308378:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7010000003b0 [20421:20421:0315/223624.602265:7731308412:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.602324:7731308470:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7010000003b0 [20421:20421:0315/223624.602362:7731308508:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.602421:7731308567:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7010000003b0 [20421:20421:0315/223624.602454:7731308603:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x7010000003c0 with delay 54000 [20421:20421:0315/223624.604079:7731310227:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7010000003c0 [20421:20421:0315/223624.604120:7731310267:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x7010000003c0 with delay 1000 [20421:20421:0315/223624.604179:7731310326:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x7010000003c0 [20421:20421:0315/223624.604213:7731310359:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x7010000003c0 with delay 1000 [20421:20421:0315/223624.604271:7731310417:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x7010000003c0 [20421:20421:0315/223624.604304:7731310451:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x7010000003c0 with delay 1000 [20421:20421:0315/223624.604363:7731310509:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x7010000003c0 [20421:20421:0315/223624.604396:7731310542:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x7010000003c0 with delay 1000 [20421:20421:0315/223624.604454:7731310601:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x7010000003c0 [20421:20421:0315/223624.604487:7731310634:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x7010000003c0 with delay 1000 [20421:20421:0315/223624.604548:7731310695:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x7010000003c0 [20421:20421:0315/223624.604582:7731310729:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x7010000003c0 with delay 1000 [20421:20421:0315/223624.604645:7731310799:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x7010000003c0 [20421:20421:0315/223624.604686:7731310833:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7010000003b0 with delay 54000 [20421:20421:0315/223624.606261:7731312408:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7010000003b0 [20421:20421:0315/223624.606298:7731312445:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.606357:7731312504:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7010000003b0 [20421:20421:0315/223624.606391:7731312537:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.606449:7731312596:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7010000003b0 [20421:20421:0315/223624.606482:7731312629:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.606543:7731312689:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7010000003b0 [20421:20421:0315/223624.606576:7731312723:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.606634:7731312781:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7010000003b0 [20421:20421:0315/223624.606676:7731312822:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.606734:7731312881:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7010000003b0 [20421:20421:0315/223624.606767:7731312914:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.606826:7731312972:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7010000003b0 [20421:20421:0315/223624.606858:7731313005:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x7010000003c0 with delay 54000 [20421:20421:0315/223624.608447:7731314595:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x7010000003c0 [20421:20421:0315/223624.608486:7731314633:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x7010000003c0 with delay 1000 [20421:20421:0315/223624.608548:7731314695:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x7010000003c0 [20421:20421:0315/223624.608581:7731314728:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x7010000003c0 with delay 1000 [20421:20421:0315/223624.608644:7731314798:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x7010000003c0 [20421:20421:0315/223624.608685:7731314832:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x7010000003c0 with delay 1000 [20421:20421:0315/223624.608744:7731314890:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x7010000003c0 [20421:20421:0315/223624.608777:7731314924:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x7010000003c0 with delay 1000 [20421:20421:0315/223624.608835:7731314982:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x7010000003c0 [20421:20421:0315/223624.608869:7731315015:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x7010000003c0 with delay 1000 [20421:20421:0315/223624.608927:7731315073:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x7010000003c0 [20421:20421:0315/223624.608960:7731315107:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x7010000003c0 with delay 1000 [20421:20421:0315/223624.609023:7731315169:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x7010000003c0 [20421:20421:0315/223624.609055:7731315203:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7010000003b0 with delay 54000 [20421:20421:0315/223624.610657:7731316804:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7010000003b0 [20421:20421:0315/223624.610700:7731316847:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.610760:7731316907:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7010000003b0 [20421:20421:0315/223624.610793:7731316940:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.610851:7731316998:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7010000003b0 [20421:20421:0315/223624.610884:7731317031:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.610943:7731317089:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7010000003b0 [20421:20421:0315/223624.610975:7731317122:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.611039:7731317185:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7010000003b0 [20421:20421:0315/223624.611072:7731317219:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.611131:7731317277:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7010000003b0 [20421:20421:0315/223624.611163:7731317310:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7010000003b0 with delay 1000 [20421:20421:0315/223624.611222:7731317368:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7010000003b0 [20421:20421:0315/223624.611254:7731317401:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x7010000003c0 with delay 54000 [20421:20421:0315/223624.612819:7731318966:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x7010000003c0 [ OK ] ThrottleTest.ThrottlingStorm (11 ms) [8/28] ThrottleTest.ThrottlingStorm (11 ms) [ RUN ] InvalidationClientImplTest.Start [20419:20419:0315/223624.499521:7731205747:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000640 with delay 0 [20419:20419:0315/223624.500049:7731206207:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [20419:20419:0315/223624.500573:7731206724:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 0 [20419:20419:0315/223624.500670:7731206820:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000640 [20419:20419:0315/223624.500755:7731206902:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000820 [20419:20419:0315/223624.500888:7731207042:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [20419:20419:0315/223624.500999:7731207149:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000870 with delay 0 [20419:20419:0315/223624.501056:7731207203:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000870 [20419:20419:0315/223624.501092:7731207242:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [20419:20419:0315/223624.501137:7731207286:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 0 [20419:20419:0315/223624.501179:7731207327:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000820 [20419:20419:0315/223624.501227:7731207377:INFO:invalidation-client-core.cc(351)] Starting with no previous state [20419:20419:0315/223624.501278:7731207428:INFO:recurring-task.cc(55)] [Startup] Scheduling 2120 with a delay 0, Now = 210919424 [20419:20419:0315/223624.501318:7731207471:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000870 with delay 0 [20419:20419:0315/223624.501363:7731207510:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000870 [20419:20419:0315/223624.501501:7731207651:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "5781642690264872593" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [20419:20419:0315/223624.501556:7731207706:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2504 with a delay 500000, Now = 210919424 [20419:20419:0315/223624.501598:7731207747:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000820 with delay 500 [20419:20419:0315/223624.501640:7731207799:INFO:recurring-task.cc(55)] [Retry] Scheduling 2120 with a delay 60000000, Now = 210919424 [20419:20419:0315/223624.501692:7731207842:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007e0 with delay 60000 [20419:20419:0315/223624.501747:7731207896:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000820 [20419:20419:0315/223624.501827:7731207981:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.502072:7731208222:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.502362:7731208512: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: "5781642690264872593" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [20419:20419:0315/223624.502936:7731209088:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000820 with delay 0 [20419:20419:0315/223624.502997:7731209146:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000820 [20419:20419:0315/223624.503167:7731209318:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "5781642690264872593" 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" } } [20419:20419:0315/223624.503250:7731209403:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "5781642690264872593" [20419:20419:0315/223624.503297:7731209451:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [20419:20419:0315/223624.503348:7731209500:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [20419:20419:0315/223624.503395:7731209544:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000860 with delay 1200000 [20419:20419:0315/223624.503443:7731209592:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [20419:20419:0315/223624.503730:7731209884:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [20419:20419:0315/223624.503782:7731209931:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 904 with a delay 0, Now = 211419424 [20419:20419:0315/223624.503826:7731209984:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000870 with delay 0 [20419:20419:0315/223624.503956:7731210112: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 [20419:20419:0315/223624.504020:7731210168:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000870 [20419:20419:0315/223624.504153:7731210304:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000890 with delay 0 [20419:20419:0315/223624.504215:7731210368:INFO:recurring-task.cc(55)] [Retry] Scheduling 904 with a delay 10000000, Now = 211419424 [20419:20419:0315/223624.504258:7731210407:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000640 with delay 10000 [20419:20419:0315/223624.504300:7731210448:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000890 [20419:20419:0315/223624.504335:7731210485:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (16 ms) [9/28] InvalidationClientImplTest.Start (16 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [20419:20419:0315/223624.505513:7731211665:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000840 with delay 0 [20419:20419:0315/223624.505588:7731211738:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [ OK ] InvalidationClientImplTest.GenerateNonce (0 ms) [10/28] InvalidationClientImplTest.GenerateNonce (0 ms) [ RUN ] InvalidationClientImplTest.Register [20419:20419:0315/223624.506230:7731212381:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000850 with delay 0 [20419:20419:0315/223624.506298:7731212447:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [20419:20419:0315/223624.506688:7731212839:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008b0 with delay 0 [20419:20419:0315/223624.506749:7731212899:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000850 [20419:20419:0315/223624.506790:7731212938:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008b0 [20419:20419:0315/223624.506873:7731213022:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [20419:20419:0315/223624.506939:7731213095:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008f0 with delay 0 [20419:20419:0315/223624.506993:7731213141:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008f0 [20419:20419:0315/223624.507028:7731213177:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [20419:20419:0315/223624.507077:7731213226:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008b0 with delay 0 [20419:20419:0315/223624.507119:7731213267:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008b0 [20419:20419:0315/223624.507156:7731213305:INFO:invalidation-client-core.cc(351)] Starting with no previous state [20419:20419:0315/223624.507201:7731213351:INFO:recurring-task.cc(55)] [Startup] Scheduling 2600 with a delay 0, Now = 210919424 [20419:20419:0315/223624.507243:7731213393:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008f0 with delay 0 [20419:20419:0315/223624.507282:7731213429:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008f0 [20419:20419:0315/223624.507359:7731213510:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-1293412296502030006" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [20419:20419:0315/223624.507405:7731213555:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2120 with a delay 500000, Now = 210919424 [20419:20419:0315/223624.507454:7731213610:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008b0 with delay 500 [20419:20419:0315/223624.507504:7731213654:INFO:recurring-task.cc(55)] [Retry] Scheduling 2600 with a delay 60000000, Now = 210919424 [20419:20419:0315/223624.507546:7731213701:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008d0 with delay 60000 [20419:20419:0315/223624.507622:7731213771:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008b0 [20419:20419:0315/223624.507673:7731213826:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.507732:7731213881:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.507898:7731214048: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: "-1293412296502030006" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [20419:20419:0315/223624.508045:7731214195:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008b0 with delay 0 [20419:20419:0315/223624.508089:7731214239:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008b0 [20419:20419:0315/223624.508277:7731214427:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-1293412296502030006" 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" } } [20419:20419:0315/223624.508358:7731214507:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-1293412296502030006" [20419:20419:0315/223624.508403:7731214552:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [20419:20419:0315/223624.508447:7731214598:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [20419:20419:0315/223624.508488:7731214641:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008e0 with delay 1200000 [20419:20419:0315/223624.508535:7731214687:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [20419:20419:0315/223624.508688:7731214837:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [20419:20419:0315/223624.508740:7731214889:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424 [20419:20419:0315/223624.508779:7731214930:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008f0 with delay 0 [20419:20419:0315/223624.508841:7731214996: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 [20419:20419:0315/223624.508899:7731215048:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008f0 [20419:20419:0315/223624.508977:7731215126:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000910 with delay 0 [20419:20419:0315/223624.509027:7731215177:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424 [20419:20419:0315/223624.509068:7731215217:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000850 with delay 10000 [20419:20419:0315/223624.509109:7731215256:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000910 [20419:20419:0315/223624.509143:7731215292:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [20419:20419:0315/223624.509307:7731215457:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000910 with delay 0 [20419:20419:0315/223624.509356:7731215505:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000910 [20419:20419:0315/223624.509411:7731215561:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [20419:20419:0315/223624.509460:7731215608:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [20419:20419:0315/223624.509503:7731215651:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [20419:20419:0315/223624.509596:7731215754:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 2120 with a delay 500000, Now = 211469424 [20419:20419:0315/223624.509658:7731215811:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000008f0 with delay 500 [20419:20419:0315/223624.509704:7731215853:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 2792 with a delay 60000000, Now = 211469424 [20419:20419:0315/223624.509746:7731215895:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000900 with delay 60000 [20419:20419:0315/223624.509810:7731215959:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000008f0 [20419:20419:0315/223624.509859:7731216032:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.509951:7731216101:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.509992:7731216142:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [20419:20419:0315/223624.510183:7731216332: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 } } } [20419:20419:0315/223624.510356:7731216508:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.510485:7731216651:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7010000008f0 with delay 0 [20419:20419:0315/223624.510544:7731216723:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000008f0 [20419:20419:0315/223624.510901:7731217052: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 } } } } [20419:20419:0315/223624.511052:7731217202: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 [20419:20419:0315/223624.511165:7731217327:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [20419:20419:0315/223624.511320:7731217468:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [20419:20419:0315/223624.511415:7731217563:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [20419:20419:0315/223624.511720:7731217870:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000850 [ OK ] InvalidationClientImplTest.Register (8 ms) [11/28] InvalidationClientImplTest.Register (8 ms) [ RUN ] InvalidationClientImplTest.Invalidations [20419:20419:0315/223624.513545:7731219696:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000790 with delay 0 [20419:20419:0315/223624.513617:7731219766:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [20419:20419:0315/223624.514099:7731220250:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005f0 with delay 0 [20419:20419:0315/223624.514155:7731220305:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000790 [20419:20419:0315/223624.514198:7731220345:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000005f0 [20419:20419:0315/223624.514282:7731220432:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [20419:20419:0315/223624.514352:7731220506:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000910 with delay 0 [20419:20419:0315/223624.514406:7731220554:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000910 [20419:20419:0315/223624.514441:7731220591:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [20419:20419:0315/223624.514484:7731220633:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005f0 with delay 0 [20419:20419:0315/223624.514531:7731220679:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000005f0 [20419:20419:0315/223624.514568:7731220717:INFO:invalidation-client-core.cc(351)] Starting with no previous state [20419:20419:0315/223624.514626:7731220809:INFO:recurring-task.cc(55)] [Startup] Scheduling 2696 with a delay 0, Now = 210919424 [20419:20419:0315/223624.514708:7731220857:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000910 with delay 0 [20419:20419:0315/223624.514747:7731220895:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000910 [20419:20419:0315/223624.514826:7731220979:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-1588161771022843391" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [20419:20419:0315/223624.514885:7731221034:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2984 with a delay 500000, Now = 210919424 [20419:20419:0315/223624.514926:7731221075:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005f0 with delay 500 [20419:20419:0315/223624.514967:7731221116:INFO:recurring-task.cc(55)] [Retry] Scheduling 2696 with a delay 60000000, Now = 210919424 [20419:20419:0315/223624.515028:7731221178:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000560 with delay 60000 [20419:20419:0315/223624.515097:7731221247:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005f0 [20419:20419:0315/223624.515138:7731221290:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.515193:7731221342:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.515349:7731221500: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: "-1588161771022843391" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [20419:20419:0315/223624.515520:7731221669:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005f0 with delay 0 [20419:20419:0315/223624.515566:7731221715:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005f0 [20419:20419:0315/223624.515709:7731221859:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-1588161771022843391" 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" } } [20419:20419:0315/223624.515803:7731221953:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-1588161771022843391" [20419:20419:0315/223624.515869:7731222018:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [20419:20419:0315/223624.515946:7731222096:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [20419:20419:0315/223624.515987:7731222170:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008b0 with delay 1200000 [20419:20419:0315/223624.516070:7731222227:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [20419:20419:0315/223624.516221:7731222370:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [20419:20419:0315/223624.516268:7731222417:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1416 with a delay 0, Now = 211419424 [20419:20419:0315/223624.516312:7731222464:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000910 with delay 0 [20419:20419:0315/223624.516378:7731222528: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 [20419:20419:0315/223624.516431:7731222580:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000910 [20419:20419:0315/223624.516508:7731222657:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000940 with delay 0 [20419:20419:0315/223624.516560:7731222709:INFO:recurring-task.cc(55)] [Retry] Scheduling 1416 with a delay 10000000, Now = 211419424 [20419:20419:0315/223624.516601:7731222750:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000790 with delay 10000 [20419:20419:0315/223624.516658:7731222806:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000940 [20419:20419:0315/223624.516693:7731222843:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [20419:20419:0315/223624.516786:7731222936:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.516879:7731223029:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000940 with delay 0 [20419:20419:0315/223624.516923:7731223073:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000940 [20419:20419:0315/223624.517175:7731223324: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 } } } [20419:20419:0315/223624.517279:7731223429: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 [20419:20419:0315/223624.517373:7731223522: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" } [20419:20419:0315/223624.517570:7731223719:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [20419:20419:0315/223624.517686:7731223834:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [20419:20419:0315/223624.517781:7731223934:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000940 with delay 0 [20419:20419:0315/223624.517825:7731223974:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000910 with delay 0 [20419:20419:0315/223624.517927:7731224076:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x701000000920 with delay 0 [20419:20419:0315/223624.517983:7731224133:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000940 [20419:20419:0315/223624.518052:7731224202:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 2984 with a delay 500000, Now = 211519424 [20419:20419:0315/223624.518101:7731224250:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7010000005f0 with delay 500 [20419:20419:0315/223624.518154:7731224302:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000910 [20419:20419:0315/223624.518199:7731224346:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x701000000920 [20419:20419:0315/223624.518251:7731224400:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x7010000005f0 [20419:20419:0315/223624.518305:7731224455:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.518370:7731224527:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.518416:7731224573:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [20419:20419:0315/223624.518698:7731224849: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) [12/28] InvalidationClientImplTest.Invalidations (6 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [20419:20419:0315/223624.519636:7731225798:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000880 with delay 0 [20419:20419:0315/223624.519720:7731225869:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [20419:20419:0315/223624.519986:7731226136:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006e0 with delay 0 [20419:20419:0315/223624.520036:7731226186:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000880 [20419:20419:0315/223624.520079:7731226227:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006e0 [20419:20419:0315/223624.520154:7731226306:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [20419:20419:0315/223624.520223:7731226373:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008f0 with delay 0 [20419:20419:0315/223624.520273:7731226421:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008f0 [20419:20419:0315/223624.520309:7731226458:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [20419:20419:0315/223624.520356:7731226506:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006e0 with delay 0 [20419:20419:0315/223624.520396:7731226544:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006e0 [20419:20419:0315/223624.520437:7731226586:INFO:invalidation-client-core.cc(351)] Starting with no previous state [20419:20419:0315/223624.520480:7731226657:INFO:recurring-task.cc(55)] [Startup] Scheduling 2600 with a delay 0, Now = 210919424 [20419:20419:0315/223624.520548:7731226697:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000008f0 with delay 0 [20419:20419:0315/223624.520614:7731226762:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000008f0 [20419:20419:0315/223624.520703:7731226852:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "4930591265906946617" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [20419:20419:0315/223624.520754:7731226904:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 3464 with a delay 500000, Now = 210919424 [20419:20419:0315/223624.520846:7731227000:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006e0 with delay 500 [20419:20419:0315/223624.520890:7731227048:INFO:recurring-task.cc(55)] [Retry] Scheduling 2600 with a delay 60000000, Now = 210919424 [20419:20419:0315/223624.520938:7731227094:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000710 with delay 60000 [20419:20419:0315/223624.520996:7731227146:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006e0 [20419:20419:0315/223624.521058:7731227207:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.521134:7731227287:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.521282:7731227434: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: "4930591265906946617" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [20419:20419:0315/223624.521425:7731227575:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000006e0 with delay 0 [20419:20419:0315/223624.521467:7731227618:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006e0 [20419:20419:0315/223624.521601:7731227751:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "4930591265906946617" 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" } } [20419:20419:0315/223624.521675:7731227827:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "4930591265906946617" [20419:20419:0315/223624.521720:7731227869:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [20419:20419:0315/223624.521765:7731227914:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [20419:20419:0315/223624.521806:7731227955:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005c0 with delay 1200000 [20419:20419:0315/223624.521851:7731228029:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [20419:20419:0315/223624.522035:7731228195:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [20419:20419:0315/223624.522090:7731228239:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424 [20419:20419:0315/223624.522135:7731228285:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008f0 with delay 0 [20419:20419:0315/223624.522213:7731228387: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 [20419:20419:0315/223624.522290:7731228438:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000008f0 [20419:20419:0315/223624.522370:7731228519:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005e0 with delay 0 [20419:20419:0315/223624.522420:7731228570:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424 [20419:20419:0315/223624.522462:7731228612:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000880 with delay 10000 [20419:20419:0315/223624.522500:7731228648:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005e0 [20419:20419:0315/223624.522542:7731228694:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [20419:20419:0315/223624.522606:7731228755:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.522679:7731228831:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000005e0 with delay 0 [20419:20419:0315/223624.522722:7731228873:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000005e0 [20419:20419:0315/223624.522870:7731229026: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 } } [20419:20419:0315/223624.522960:7731229110: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 [20419:20419:0315/223624.523010:7731229165:INFO:protocol-handler.cc(294)] Adding subtree: { } [20419:20419:0315/223624.523058:7731229207:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 3464 with a delay 500000, Now = 211469424 [20419:20419:0315/223624.523099:7731229248:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000008f0 with delay 500 [20419:20419:0315/223624.523143:7731229292:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [20419:20419:0315/223624.523448:7731229602: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 } [20419:20419:0315/223624.523535:7731229685:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000008f0 [20419:20419:0315/223624.523580:7731229729:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.523705:7731229855:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.523750:7731229899:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [20419:20419:0315/223624.525782:7731231935: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 } } [20419:20419:0315/223624.526181:7731232331:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000880 [ OK ] InvalidationClientImplTest.ServerRequests (8 ms) [13/28] InvalidationClientImplTest.ServerRequests (8 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [20419:20419:0315/223624.527988:7731234140:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 0 [20419:20419:0315/223624.528063:7731234213:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [20419:20419:0315/223624.528343:7731234499:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006e0 with delay 0 [20419:20419:0315/223624.528394:7731234548:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000510 [20419:20419:0315/223624.528445:7731234593:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006e0 [20419:20419:0315/223624.528522:7731234672:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [20419:20419:0315/223624.528594:7731234744:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004a0 with delay 0 [20419:20419:0315/223624.528644:7731234801:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004a0 [20419:20419:0315/223624.528689:7731234839:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [20419:20419:0315/223624.528731:7731234881:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006e0 with delay 0 [20419:20419:0315/223624.528773:7731234922:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000006e0 [20419:20419:0315/223624.528814:7731234963:INFO:invalidation-client-core.cc(351)] Starting with no previous state [20419:20419:0315/223624.528861:7731235014:INFO:recurring-task.cc(55)] [Startup] Scheduling 2984 with a delay 0, Now = 210919424 [20419:20419:0315/223624.528904:7731235056:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004a0 with delay 0 [20419:20419:0315/223624.528946:7731235094:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004a0 [20419:20419:0315/223624.529022:7731235172:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-6829962264747171846" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [20419:20419:0315/223624.529073:7731235222:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2600 with a delay 500000, Now = 210919424 [20419:20419:0315/223624.529116:7731235266:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000006e0 with delay 500 [20419:20419:0315/223624.529159:7731235308:INFO:recurring-task.cc(55)] [Retry] Scheduling 2984 with a delay 60000000, Now = 210919424 [20419:20419:0315/223624.529200:7731235350:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000490 with delay 60000 [20419:20419:0315/223624.529251:7731235405:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006e0 [20419:20419:0315/223624.529296:7731235445:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.529354:7731235505:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.529500:7731235652: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: "-6829962264747171846" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [20419:20419:0315/223624.529633:7731235794:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000006e0 with delay 0 [20419:20419:0315/223624.529690:7731235839:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000006e0 [20419:20419:0315/223624.529825:7731235975:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-6829962264747171846" 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" } } [20419:20419:0315/223624.529927:7731236081:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-6829962264747171846" [20419:20419:0315/223624.529981:7731236134:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [20419:20419:0315/223624.530028:7731236178:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [20419:20419:0315/223624.530072:7731236221:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004f0 with delay 1200000 [20419:20419:0315/223624.530118:7731236267:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [20419:20419:0315/223624.530264:7731236429:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [20419:20419:0315/223624.530322:7731236478:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424 [20419:20419:0315/223624.530370:7731236519:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004a0 with delay 0 [20419:20419:0315/223624.530435:7731236585: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 [20419:20419:0315/223624.530489:7731236638:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004a0 [20419:20419:0315/223624.530570:7731236719:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000003a0 with delay 0 [20419:20419:0315/223624.530622:7731236771:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424 [20419:20419:0315/223624.530673:7731236822:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000510 with delay 10000 [20419:20419:0315/223624.530711:7731236859:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000003a0 [20419:20419:0315/223624.530753:7731236903:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [20419:20419:0315/223624.530814:7731236967:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.530879:7731237032:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000003a0 with delay 0 [20419:20419:0315/223624.530922:7731237074:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7010000003a0 [20419:20419:0315/223624.531052:7731237202: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" } } [20419:20419:0315/223624.531137:7731237286: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 [20419:20419:0315/223624.531188:7731237337:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [20419:20419:0315/223624.531574:7731237724:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000510 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (5 ms) [14/28] InvalidationClientImplTest.IncomingErrorMessage (5 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [20419:20419:0315/223624.533263:7731239415:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000760 with delay 0 [20419:20419:0315/223624.533334:7731239484:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [20419:20419:0315/223624.533714:7731239866:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000840 with delay 0 [20419:20419:0315/223624.533785:7731239935:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000760 [20419:20419:0315/223624.533833:7731239980:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000840 [20419:20419:0315/223624.533942:7731240091:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [20419:20419:0315/223624.534035:7731240185:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000920 with delay 0 [20419:20419:0315/223624.534083:7731240232:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000920 [20419:20419:0315/223624.534119:7731240273:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [20419:20419:0315/223624.534163:7731240325:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000840 with delay 0 [20419:20419:0315/223624.534219:7731240368:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000840 [20419:20419:0315/223624.534256:7731240405:INFO:invalidation-client-core.cc(351)] Starting with no previous state [20419:20419:0315/223624.534303:7731240452:INFO:recurring-task.cc(55)] [Startup] Scheduling 2696 with a delay 0, Now = 210919424 [20419:20419:0315/223624.534345:7731240497:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000920 with delay 0 [20419:20419:0315/223624.534389:7731240537:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000920 [20419:20419:0315/223624.534466:7731240616:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "5413994998061872273" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [20419:20419:0315/223624.534510:7731240663:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2984 with a delay 500000, Now = 210919424 [20419:20419:0315/223624.534552:7731240704:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000840 with delay 500 [20419:20419:0315/223624.534593:7731240742:INFO:recurring-task.cc(55)] [Retry] Scheduling 2696 with a delay 60000000, Now = 210919424 [20419:20419:0315/223624.534634:7731240794:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005f0 with delay 60000 [20419:20419:0315/223624.534698:7731240848:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000840 [20419:20419:0315/223624.534778:7731240928:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.534857:7731241007:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.535013:7731241163: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: "5413994998061872273" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [20419:20419:0315/223624.535155:7731241305:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000840 with delay 0 [20419:20419:0315/223624.535200:7731241349:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000840 [20419:20419:0315/223624.535334:7731241483:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "5413994998061872273" 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" } } [20419:20419:0315/223624.535399:7731241549:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "5413994998061872273" [20419:20419:0315/223624.535443:7731241592:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [20419:20419:0315/223624.535488:7731241638:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [20419:20419:0315/223624.535539:7731241689:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000910 with delay 1200000 [20419:20419:0315/223624.535585:7731241734:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [20419:20419:0315/223624.535749:7731241899:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [20419:20419:0315/223624.535798:7731241948:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424 [20419:20419:0315/223624.535844:7731241999:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000920 with delay 0 [20419:20419:0315/223624.535915:7731242064: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 [20419:20419:0315/223624.535966:7731242114:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000920 [20419:20419:0315/223624.536045:7731242194:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000930 with delay 0 [20419:20419:0315/223624.536093:7731242245:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424 [20419:20419:0315/223624.536135:7731242284:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000760 with delay 10000 [20419:20419:0315/223624.536178:7731242325:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000930 [20419:20419:0315/223624.536213:7731242368:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [20419:20419:0315/223624.536293:7731242442:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000930 with delay 0 [20419:20419:0315/223624.536339:7731242489:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000930 [20419:20419:0315/223624.536401:7731242550:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [20419:20419:0315/223624.536470:7731242619:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 2984 with a delay 500000, Now = 211469424 [20419:20419:0315/223624.536515:7731242664:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000920 with delay 500 [20419:20419:0315/223624.536558:7731242708:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 2120 with a delay 60000000, Now = 211469424 [20419:20419:0315/223624.536599:7731242749:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000940 with delay 60000 [20419:20419:0315/223624.536667:7731242816:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000920 [20419:20419:0315/223624.536725:7731242874:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.536778:7731242939:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.536840:7731243033:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [20419:20419:0315/223624.537037:7731243193: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 } } } [20419:20419:0315/223624.537142:7731243291:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.537202:7731243351:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x701000000920 with delay 0 [20419:20419:0315/223624.537248:7731243397:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x701000000920 [20419:20419:0315/223624.537394:7731243544: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" } } [20419:20419:0315/223624.537474:7731243624: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 [20419:20419:0315/223624.537516:7731243703:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [20419:20419:0315/223624.537668:7731243818:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [20419:20419:0315/223624.538058:7731244208:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000760 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (7 ms) [15/28] InvalidationClientImplTest.IncomingAuthErrorMessage (7 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [20419:20419:0315/223624.539786:7731245939:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005e0 with delay 0 [20419:20419:0315/223624.539868:7731246018:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [20419:20419:0315/223624.540136:7731246286:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 0 [20419:20419:0315/223624.540184:7731246334:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000005e0 [20419:20419:0315/223624.540228:7731246376:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000510 [20419:20419:0315/223624.540301:7731246454:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [20419:20419:0315/223624.540373:7731246523:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007f0 with delay 0 [20419:20419:0315/223624.540431:7731246578:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000007f0 [20419:20419:0315/223624.540466:7731246616:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [20419:20419:0315/223624.540510:7731246660:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 0 [20419:20419:0315/223624.540550:7731246706:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000510 [20419:20419:0315/223624.540602:7731246762:INFO:invalidation-client-core.cc(351)] Starting with no previous state [20419:20419:0315/223624.540677:7731246828:INFO:recurring-task.cc(55)] [Startup] Scheduling 2888 with a delay 0, Now = 210919424 [20419:20419:0315/223624.540721:7731246872:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007f0 with delay 0 [20419:20419:0315/223624.540764:7731246913:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000007f0 [20419:20419:0315/223624.540843:7731246999:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-8198242419052302964" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [20419:20419:0315/223624.540897:7731247046:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 2696 with a delay 500000, Now = 210919424 [20419:20419:0315/223624.540938:7731247088:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000510 with delay 500 [20419:20419:0315/223624.540977:7731247129:INFO:recurring-task.cc(55)] [Retry] Scheduling 2888 with a delay 60000000, Now = 210919424 [20419:20419:0315/223624.541018:7731247170:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000610 with delay 60000 [20419:20419:0315/223624.541071:7731247221:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000510 [20419:20419:0315/223624.541114:7731247263:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.541172:7731247334:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.541336:7731247489: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: "-8198242419052302964" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [20419:20419:0315/223624.541478:7731247627:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000510 with delay 0 [20419:20419:0315/223624.541520:7731247672:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000510 [20419:20419:0315/223624.541664:7731247815:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-8198242419052302964" 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" } } [20419:20419:0315/223624.541727:7731247876:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-8198242419052302964" [20419:20419:0315/223624.541775:7731247925:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [20419:20419:0315/223624.541821:7731247970:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [20419:20419:0315/223624.541893:7731248047:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000008b0 with delay 1200000 [20419:20419:0315/223624.541948:7731248097:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [20419:20419:0315/223624.542086:7731248236:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [20419:20419:0315/223624.542141:7731248290:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424 [20419:20419:0315/223624.542190:7731248339:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000007f0 with delay 0 [20419:20419:0315/223624.542256:7731248409: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 [20419:20419:0315/223624.542312:7731248461:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000007f0 [20419:20419:0315/223624.542390:7731248540:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000410 with delay 0 [20419:20419:0315/223624.542441:7731248591:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424 [20419:20419:0315/223624.542483:7731248633:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000005e0 with delay 10000 [20419:20419:0315/223624.542522:7731248669:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000410 [20419:20419:0315/223624.542557:7731248710:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [20419:20419:0315/223624.542620:7731248770:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000410 with delay 0 [20419:20419:0315/223624.542674:7731248824:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000410 [20419:20419:0315/223624.542732:7731248882:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [20419:20419:0315/223624.542801:7731248953:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 2696 with a delay 500000, Now = 211469424 [20419:20419:0315/223624.542848:7731249005:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000007f0 with delay 500 [20419:20419:0315/223624.542897:7731249046:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 2504 with a delay 60000000, Now = 211469424 [20419:20419:0315/223624.542938:7731249088:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7010000004b0 with delay 60000 [20419:20419:0315/223624.542997:7731249146:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7010000007f0 [20419:20419:0315/223624.543043:7731249192:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.543110:7731249265:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.543165:7731249319:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [20419:20419:0315/223624.543357:7731249507: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 } } } [20419:20419:0315/223624.543689:7731249839:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7010000005e0 [20419:20419:0315/223624.544844:7731250996:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000610 [20419:20419:0315/223624.544899:7731251046:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x7010000004b0 [20419:20419:0315/223624.544960:7731251114: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 [20419:20419:0315/223624.545005:7731251156:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [20419:20419:0315/223624.545097:7731251248: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 } [20419:20419:0315/223624.545151:7731251300:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2696 with a delay 500000, Now = 271469424 [20419:20419:0315/223624.545194:7731251343:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x701000000610 with delay 500 [20419:20419:0315/223624.545236:7731251386:INFO:recurring-task.cc(55)] [Retry] Scheduling 2504 with a delay 60000000, Now = 271469424 [20419:20419:0315/223624.545284:7731251433:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7010000005e0 with delay 60000 [20419:20419:0315/223624.545338:7731251487:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x701000000610 [20419:20419:0315/223624.545382:7731251532:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.545442:7731251591:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.545483:7731251632:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [20419:20419:0315/223624.545663:7731251814: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) [16/28] InvalidationClientImplTest.NetworkTimeouts (8 ms) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary [20419:20419:0315/223624.547713:7731253865:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000800 with delay 0 [20419:20419:0315/223624.547788:7731253938:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [20419:20419:0315/223624.548032:7731254186:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004d0 with delay 0 [20419:20419:0315/223624.548081:7731254233:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000800 [20419:20419:0315/223624.548123:7731254271:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004d0 [20419:20419:0315/223624.548199:7731254349:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [20419:20419:0315/223624.548266:7731254417:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0 [20419:20419:0315/223624.548319:7731254467:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0 [20419:20419:0315/223624.548357:7731254508:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [20419:20419:0315/223624.548405:7731254555:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004d0 with delay 0 [20419:20419:0315/223624.548450:7731254598:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004d0 [20419:20419:0315/223624.548486:7731254636:INFO:invalidation-client-core.cc(351)] Starting with no previous state [20419:20419:0315/223624.548528:7731254680:INFO:recurring-task.cc(55)] [Startup] Scheduling 3464 with a delay 0, Now = 210919424 [20419:20419:0315/223624.548571:7731254723:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0 [20419:20419:0315/223624.548613:7731254761:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0 [20419:20419:0315/223624.548701:7731254851:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-2937316866299318971" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [20419:20419:0315/223624.548754:7731254903:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 3080 with a delay 500000, Now = 210919424 [20419:20419:0315/223624.548795:7731254945:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004d0 with delay 500 [20419:20419:0315/223624.548838:7731254987:INFO:recurring-task.cc(55)] [Retry] Scheduling 3464 with a delay 60000000, Now = 210919424 [20419:20419:0315/223624.548888:7731255037:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000007a0 with delay 60000 [20419:20419:0315/223624.548939:7731255092:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004d0 [20419:20419:0315/223624.548983:7731255132:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.549039:7731255189:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.549213:7731255365: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: "-2937316866299318971" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [20419:20419:0315/223624.549347:7731255499:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004d0 with delay 0 [20419:20419:0315/223624.549400:7731255549:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004d0 [20419:20419:0315/223624.549540:7731255689:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-2937316866299318971" 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" } } [20419:20419:0315/223624.549604:7731255758:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-2937316866299318971" [20419:20419:0315/223624.549659:7731255811:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [20419:20419:0315/223624.549705:7731255855:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424 [20419:20419:0315/223624.549747:7731255897:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000007f0 with delay 1200000 [20419:20419:0315/223624.549793:7731255942:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [20419:20419:0315/223624.549967:7731256119:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [20419:20419:0315/223624.550016:7731256167:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424 [20419:20419:0315/223624.550057:7731256206:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004b0 with delay 0 [20419:20419:0315/223624.550122:7731256275: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 [20419:20419:0315/223624.550179:7731256327:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004b0 [20419:20419:0315/223624.550258:7731256408:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000410 with delay 0 [20419:20419:0315/223624.550309:7731256472:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424 [20419:20419:0315/223624.550378:7731256528:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000800 with delay 10000 [20419:20419:0315/223624.550424:7731256572:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000410 [20419:20419:0315/223624.550463:7731256612:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [20419:20419:0315/223624.550528:7731256678:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.550582:7731256736:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x701000000410 with delay 0 [20419:20419:0315/223624.550626:7731256775:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x701000000410 [20419:20419:0315/223624.550740:7731256892: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" } } [20419:20419:0315/223624.551028:7731257178:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000800 [20419:20419:0315/223624.552055:7731258205: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) [17/28] InvalidationClientImplTest.NoRegistrationSummary (5 ms) [ RUN ] InvalidationClientImplTest.Heartbeats [20419:20419:0315/223624.552838:7731258995:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000660 with delay 0 [20419:20419:0315/223624.552917:7731259066:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [20419:20419:0315/223624.553160:7731259317:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000530 with delay 0 [20419:20419:0315/223624.553211:7731259360:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000660 [20419:20419:0315/223624.553257:7731259404:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000530 [20419:20419:0315/223624.553332:7731259482:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [20419:20419:0315/223624.553401:7731259551:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0 [20419:20419:0315/223624.553451:7731259599:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0 [20419:20419:0315/223624.553486:7731259636:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [20419:20419:0315/223624.553529:7731259679:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000530 with delay 0 [20419:20419:0315/223624.553573:7731259721:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000530 [20419:20419:0315/223624.553609:7731259758:INFO:invalidation-client-core.cc(351)] Starting with no previous state [20419:20419:0315/223624.553661:7731259813:INFO:recurring-task.cc(55)] [Startup] Scheduling 2792 with a delay 0, Now = 210919424 [20419:20419:0315/223624.553704:7731259857:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0 [20419:20419:0315/223624.553746:7731259894:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0 [20419:20419:0315/223624.553823:7731259972:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "2344722571060724564" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [20419:20419:0315/223624.553903:7731260054:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 3464 with a delay 500000, Now = 210919424 [20419:20419:0315/223624.553950:7731260099:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000530 with delay 500 [20419:20419:0315/223624.553997:7731260147:INFO:recurring-task.cc(55)] [Retry] Scheduling 2792 with a delay 60000000, Now = 210919424 [20419:20419:0315/223624.554037:7731260189:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000480 with delay 60000 [20419:20419:0315/223624.554091:7731260243:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000530 [20419:20419:0315/223624.554133:7731260283:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.554194:7731260344:INFO:invalidation-client-core.cc(488)] Return client token = "" [20419:20419:0315/223624.554346:7731260501: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: "2344722571060724564" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [20419:20419:0315/223624.554480:7731260630:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000530 with delay 0 [20419:20419:0315/223624.554527:7731260677:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000530 [20419:20419:0315/223624.554672:7731260822:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "2344722571060724564" 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" } } [20419:20419:0315/223624.554779:7731260932:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "2344722571060724564" [20419:20419:0315/223624.554824:7731260974:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [20419:20419:0315/223624.554876:7731261026:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424 [20419:20419:0315/223624.554917:7731261066:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000410 with delay 1200000 [20419:20419:0315/223624.554962:7731261112:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [20419:20419:0315/223624.555105:7731261257:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [20419:20419:0315/223624.555149:7731261298:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1800 with a delay 0, Now = 211419424 [20419:20419:0315/223624.555191:7731261340:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004b0 with delay 0 [20419:20419:0315/223624.555251:7731261403: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 [20419:20419:0315/223624.555307:7731261455:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004b0 [20419:20419:0315/223624.555385:7731261535:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7010000004d0 with delay 0 [20419:20419:0315/223624.555436:7731261586:INFO:recurring-task.cc(55)] [Retry] Scheduling 1800 with a delay 10000000, Now = 211419424 [20419:20419:0315/223624.555478:7731261628:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x701000000660 with delay 10000 [20419:20419:0315/223624.555517:7731261665:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000004d0 [20419:20419:0315/223624.555552:7731261704:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [20419:20419:0315/223624.555848:7731262002:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x701000000660 [20419:20419:0315/223624.557020:7731263168:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x701000000480 [20419:20419:0315/223624.584416:7731290567:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x701000000410 [20419:20419:0315/223624.584506:7731290662:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [20419:20419:0315/223624.584585:7731290734:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [20419:20419:0315/223624.584638:7731290795:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [20419:20419:0315/223624.584879:7731291029: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 } [20419:20419:0315/223624.584931:7731291081:INFO:recurring-task.cc(55)] [Send-info] Scheduling 3464 with a delay 500000, Now = 1411419424 [20419:20419:0315/223624.584984:7731291134:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000480 with delay 500 [20419:20419:0315/223624.585033:7731291183:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424 [20419:20419:0315/223624.585076:7731291225:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x701000000660 with delay 1200000 [20419:20419:0315/223624.585126:7731291274:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x701000000480 [20419:20419:0315/223624.585184:7731291333:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.585331:7731291481:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [20419:20419:0315/223624.585386:7731291536:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [20419:20419:0315/223624.585662:7731291813: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 (35 ms) [18/28] InvalidationClientImplTest.Heartbeats (35 ms) [ RUN ] ProtocolHandlerTest.SendInitializeOnly [20420:20420:0315/223624.563441:7731269699:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000540 with delay 0 [20420:20420:0315/223624.564209:7731270373:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000540 [20420:20420:0315/223624.564617:7731270768: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 } [20420:20420:0315/223624.564702:7731270852:INFO:recurring-task.cc(55)] [Startup] Scheduling 2120 with a delay 500000, Now = 210919424 [20420:20420:0315/223624.564758:7731270908:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000005e0 with delay 500 [20420:20420:0315/223624.564830:7731270986:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7010000005e0 [20420:20420:0315/223624.565186:7731271345: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 (8 ms) [19/28] ProtocolHandlerTest.SendInitializeOnly (8 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [20420:20420:0315/223624.566924:7731273076:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "fake nonce" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } token_control_message: { new_token: "new token" } } [ OK ] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms) [20/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes [20420:20420:0315/223624.567509:7731273659:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004d0 with delay 0 [20420:20420:0315/223624.567678:7731273828:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000500 with delay 0 [20420:20420:0315/223624.567743:7731273898:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000480 with delay 0 [20420:20420:0315/223624.567824:7731273981:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004c0 with delay 0 [20420:20420:0315/223624.567875:7731274022:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000470 with delay 0 [20420:20420:0315/223624.567925:7731274087:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7010000004b0 with delay 0 [20420:20420:0315/223624.568499:7731274654:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004d0 [20420:20420:0315/223624.568644:7731274809: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 } [20420:20420:0315/223624.568736:7731274885:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2408 with a delay 500000, Now = 210919424 [20420:20420:0315/223624.568798:7731274953:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000630 with delay 500 [20420:20420:0315/223624.568857:7731275005:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000500 [20420:20420:0315/223624.568904:7731275051:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000480 [20420:20420:0315/223624.568940:7731275086:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004c0 [20420:20420:0315/223624.568984:7731275131:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000470 [20420:20420:0315/223624.569022:7731275169:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7010000004b0 [20420:20420:0315/223624.569098:7731275257:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [20420:20420:0315/223624.569200:7731275378:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000630 [20420:20420:0315/223624.569420:7731275575:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [20420:20420:0315/223624.577509:7731283668: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 (11 ms) [21/28] ProtocolHandlerTest.SendMultipleMessageTypes (11 ms) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage [20420:20420:0315/223624.579808:7731285959: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) [22/28] ProtocolHandlerTest.IncomingCompositeMessage (1 ms) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage [20420:20420:0315/223624.580557:7731286719: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 } } [20420:20420:0315/223624.580678:7731286828: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" } [20420:20420:0315/223624.580784:7731286933: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 } } [20420:20420:0315/223624.580906:7731287056: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) [23/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch [20420:20420:0315/223624.581442:7731287592: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 } } [20420:20420:0315/223624.581581:7731287731: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) [24/28] ProtocolHandlerTest.MajorVersionMismatch (0 ms) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch [20420:20420:0315/223624.582140:7731288290: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) [25/28] ProtocolHandlerTest.MinorVersionMismatch (1 ms) [ RUN ] ProtocolHandlerTest.ConfigMessage [20420:20420:0315/223624.582715:7731288872: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" } } [20420:20420:0315/223624.582791:7731288941:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000400 with delay 0 [20420:20420:0315/223624.582839:7731288991:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x701000000400 [20420:20420:0315/223624.582935:7731289090: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 } [20420:20420:0315/223624.583005:7731289159:INFO:recurring-task.cc(55)] [Send-info] Scheduling 2792 with a delay 500000, Now = 210919424 [20420:20420:0315/223624.583053:7731289209:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x701000000410 with delay 500 [20420:20420:0315/223624.583111:7731289263:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x701000000410 [20420:20420:0315/223624.583164:7731289313:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 [ OK ] ProtocolHandlerTest.ConfigMessage (44 ms) [26/28] ProtocolHandlerTest.ConfigMessage (44 ms) [ RUN ] ProtocolHandlerTest.ErrorMessage [20420:20420:0315/223624.627790:7731333956:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.ErrorMessage (1 ms) [27/28] ProtocolHandlerTest.ErrorMessage (1 ms) [ RUN ] ProtocolHandlerTest.TokenMismatch [20420:20420:0315/223624.628868:7731335031: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) [28/28] ProtocolHandlerTest.TokenMismatch (1 ms) SUCCESS: all tests passed. Tests took 0 seconds. 2019-03-18 07:19:22,693 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmpffYNcU/43a9f7dcde48e810'] 2019-03-18 07:19:22,694 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmpffYNcU/43a9f7dcde48e810/output.json'] 2019-03-18 07:19:22,694 - 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": 1552918168087415, "id": "8918640994938152752", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ChromiumOS MSan Tests/11867", "builder:Linux ChromiumOS MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/532a82810a40d3bbdbe66eafc6de66ec01252210", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ChromiumOS MSan Builder", "parent_buildnumber:12036", "scheduler_invocation_id:9084071057514182576", "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": 11867, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "991ab98f113f5f51ec87d767b45523b19cd15b9e", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "got_revision_cp": "refs/heads/master@{#641568}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "got_webrtc_revision": "df644be3536b61256ab9e22bb0891a8b6a1d01c2", "got_webrtc_revision_cp": "refs/heads/master@{#27155}", "mastername": "chromium.memory", "parent_buildername": "Linux ChromiumOS MSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "991ab98f113f5f51ec87d767b45523b19cd15b9e", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "parent_got_revision_cp": "refs/heads/master@{#641568}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "parent_got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "parent_got_webrtc_revision": "df644be3536b61256ab9e22bb0891a8b6a1d01c2", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27155}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "swarm_hashes": {"accessibility_unittests": "77657a56215abce527f179cee0b495540928de3c", "angle_unittests": "b70d85c9f3906f94924eb11e9d5b122cab28d065", "app_list_unittests": "35164ac5e91cd2b46f73d4ba283d5c84914334bc", "app_shell_unittests": "bf5d079a569b62e3a5fe40faaa54ce7be94804d2", "ash_unittests": "92e721e6e6dc9a022238e9af36714397aaecfda6", "aura_unittests": "e7830d3a8705864888ad19b3bbc249aac7973950", "base_unittests": "0f9cb3c1577a282cc56e069a09eaa43185b710ef", "blink_common_unittests": "7117068b032ea3df34fbdc432a4fef66bc8f1a26", "blink_fuzzer_unittests": "7659fef36aa2db42cdfedf8a5d58dcbad19a9f14", "blink_heap_unittests": "688ab4072e0d5c14218d893d71ff8d01f41d71ba", "blink_platform_unittests": "df2391e47f99216ba7179ede45f711dca1968231", "blink_unittests": "b0c9e25c3d60d64eb6dde3972ca9de338f76325b", "boringssl_crypto_tests": "8ed296da9458a249b233d884ec7a2c74fbe56c3b", "boringssl_ssl_tests": "a4326eec2bbc8835563d6bb4abe7fee2aaf43007", "browser_tests": "99727d3cee82fcfd1927e15e93eb88ba343f1609", "cacheinvalidation_unittests": "26eb11a34f57da9a2abf246039845ba8f72fdd47", "capture_unittests": "bffb4c1c9c5f890576e6f77d35a45bb637438756", "cast_unittests": "6bd2524dcf68198b1313b394cb3f8f299cc88ce4", "cc_unittests": "9565b45514699c5fc05471a854ea06d31c54173a", "chrome_app_unittests": "5a48a2e30fe958a44a8fa98b0e6b1977c84e7e7f", "chromedriver_unittests": "15fdf9f3c582ed26e8fd30318df3d82459455274", "chromeos_components_unittests": "47a36331945a75c288436520a9bbf452675d7165", "chromeos_unittests": "d45f2b5fb6d312ad99957ebe82bdcc71a44a79fb", "components_browsertests": "66505cd0e83c70434c54bd5d2ac4345cff14c0b2", "components_unittests": "a4de17137c0d9b2a7e2c133835c3ec06a383a054", "compositor_unittests": "6071f780b1e0776b87b9998f5757953f5b124199", "content_browsertests": "9703f6ffc96540eb1d309aea9a43cfed79c1d2ff", "content_unittests": "a19c55902c23646cd1902fb674f36c56b9099a7b", "crypto_unittests": "dc61523e2da78e5e3865f8c03745e26630cfb2de", "dbus_unittests": "7b013593eb0e3f6907797ff355c239fba715709c", "device_unittests": "78da84d8557b2eeed4cebc8f46d6dd89e7ba4a49", "display_unittests": "e7e20dae68e9ffb75e00d239fdaf9b2ec137481c", "events_unittests": "acc9f6c8f34fa796a0766f6267c88ee00d4f71f7", "exo_unittests": "c604ffa0540d8ff736396417b0550aee55483c06", "extensions_browsertests": "8b635d8bf7a5a567c93f7648df25fea89921655a", "extensions_unittests": "c170dec454779ba0e124f56d048e3e7e9283f6f7", "filesystem_service_unittests": "e1746e4927ad2c136033a0f1ac64e4fb3bc0fe03", "gcm_unit_tests": "446264c5193fbc28322314b8be3463d39653c92a", "gfx_unittests": "b0d8752f97bc13bb0f95fde7e65cb59fc5d910ef", "gin_unittests": "af15a210bb7c9153f8464b8029a46b3eb9fcb600", "google_apis_unittests": "90b841b69dbe7d966432a089d7b3627fb54ef078", "gpu_unittests": "009e6220ece2c3f9c043a21d205a4fd60f7268b5", "interactive_ui_tests": "14e5cfd3e71748aa3d5e0d6e8847b165db74893f", "ipc_tests": "c45361febd0e07a60e42aa6c4b7718d2750c9362", "jingle_unittests": "e64947b30eae559fdf3cb4ba1ea12d2a9c22da2e", "keyboard_unittests": "2645c8d6574f077cab7e5c97b0c9b180655d0255", "latency_unittests": "99e3d7098a7f4608f74bfee0056f617250ea095f", "leveldb_service_unittests": "cb8dd4976b4ea9559dbd20cc13792bda0c7299f4", "libjingle_xmpp_unittests": "0200181537eeab3d725bb79beca8b2ce0009c12d", "media_blink_unittests": "3299f8f7b2d8c018b46946e265bbe84778383c71", "media_service_unittests": "546736fe867aada5d9f87d73262b0f0b54313500", "media_unittests": "610c2a0d368840a1f18f81b75ac26759aa7505c1", "message_center_unittests": "de1ca4f9764710310a0b830bb8a4f32ef185fc0f", "midi_unittests": "f39508e7bbfa64eb85dcd5d574eeac09ba3b0e61", "mojo_core_unittests": "de7aaeffadcb1a9c67e2deb5cb5df0a6553ada51", "mojo_unittests": "37680db7fde79a04370e560cf0ecc6172e515f50", "nacl_helper_nonsfi_unittests": "5662230fb325b915ae13bdc32e1e245886751f38", "nacl_loader_unittests": "359fb99e32700baa996f88023774c0a77f41e77b", "native_theme_unittests": "ad74f3ff4657247e2d09d693cef2d00132581dc6", "net_unittests": "6101a7c65994259547f724500701ef44b4219941", "ozone_gl_unittests": "0a26be0d420e99daedcfda726dc58e7dfaf4790f", "ozone_unittests": "87d00bbe11ed1ce6acabbfe29bf27455e90edc6d", "ozone_x11_unittests": "c4642eb7bf276f1f4cad532d706fa68b42889269", "pdf_unittests": "0ce52596a8e994194363b5874cccb39b6a680726", "ppapi_unittests": "4886f144adcc9f64b43ed05517cce63d2023bd4f", "printing_unittests": "1f160dc72793167fe0e6242b2295c960179169e4", "remoting_unittests": "60df526f3b416301d4623b8055b2e807d2caf62b", "sandbox_linux_unittests": "bef5eab721804ec7fd185ef9253fb7e026d45626", "service_manager_unittests": "9409cc2b98aed18f2d44f192acb9b5cb2f180716", "shell_dialogs_unittests": "698aef2d5db64d6bf57fb4d8a4514b1b7d4f0170", "skia_unittests": "a11ae40bab8a2d11dc4c55b21c794364c6c62d44", "snapshot_unittests": "431a7c5a79fd17f81335dd35882e78b8a5d93f2b", "sql_unittests": "643df51f01c4a4daf208dc355a860174693eaec5", "storage_unittests": "cbe22c79d0d7290c822f03ee4dcdda90abff55fd", "sync_integration_tests": "6c9690aa5038db40259d53ab9a9bef18216a5677", "traffic_annotation_auditor_unittests": "9926ad158e1902d58281f6e0c53b8840ed663313", "ui_base_unittests": "f22d951e45ee62e1991de3f38cf6602221ec6e68", "ui_chromeos_unittests": "f31d765397198f6352e73a2dad214a37ff7fc01a", "ui_touch_selection_unittests": "1b19d833968815b61b6048e4c8ff0550795b473b", "unit_tests": "9df90e8a009d7e6f92729f574faa2d037e9a4f8a", "url_unittests": "bfeff0c5df5e3691e816bd8845135615e1a6256b", "usage_time_limit_unittests": "84c89273b65718cb89b124c71c384e6054f3319c", "views_unittests": "174830fe2afb874e36a35084a9a1fceace1b10cc", "viz_unittests": "6cf8d8a6875f95047d9622272f045f149650b7b1", "wayland_client_perftests": "3d9a1916dcd3709612ba7495f069c84cadbd0250", "wm_unittests": "9fd8a71f431d0842327f4168ca2a8220e2c71404", "wtf_unittests": "306fcdd994ab596d998968f109b00602c0cb6618"}} --summary-json /b/swarming/w/ir/tmp/t/tmp0rkFsY.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpffYNcU -o /b/swarming/w/ir/tmp/t/tmpbww3bw.json /b/swarming/w/ir/tmp/t/tmpffYNcU/43a9f7dcde48e810/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": 1552918168087415, "id": "8918640994938152752", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ChromiumOS MSan Tests/11867", "builder:Linux ChromiumOS MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/532a82810a40d3bbdbe66eafc6de66ec01252210", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ChromiumOS MSan Builder", "parent_buildnumber:12036", "scheduler_invocation_id:9084071057514182576", "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": 11867, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "991ab98f113f5f51ec87d767b45523b19cd15b9e", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "got_revision_cp": "refs/heads/master@{#641568}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "got_webrtc_revision": "df644be3536b61256ab9e22bb0891a8b6a1d01c2", "got_webrtc_revision_cp": "refs/heads/master@{#27155}", "mastername": "chromium.memory", "parent_buildername": "Linux ChromiumOS MSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "991ab98f113f5f51ec87d767b45523b19cd15b9e", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "parent_got_revision_cp": "refs/heads/master@{#641568}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "parent_got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "parent_got_webrtc_revision": "df644be3536b61256ab9e22bb0891a8b6a1d01c2", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27155}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "swarm_hashes": {"accessibility_unittests": "77657a56215abce527f179cee0b495540928de3c", "angle_unittests": "b70d85c9f3906f94924eb11e9d5b122cab28d065", "app_list_unittests": "35164ac5e91cd2b46f73d4ba283d5c84914334bc", "app_shell_unittests": "bf5d079a569b62e3a5fe40faaa54ce7be94804d2", "ash_unittests": "92e721e6e6dc9a022238e9af36714397aaecfda6", "aura_unittests": "e7830d3a8705864888ad19b3bbc249aac7973950", "base_unittests": "0f9cb3c1577a282cc56e069a09eaa43185b710ef", "blink_common_unittests": "7117068b032ea3df34fbdc432a4fef66bc8f1a26", "blink_fuzzer_unittests": "7659fef36aa2db42cdfedf8a5d58dcbad19a9f14", "blink_heap_unittests": "688ab4072e0d5c14218d893d71ff8d01f41d71ba", "blink_platform_unittests": "df2391e47f99216ba7179ede45f711dca1968231", "blink_unittests": "b0c9e25c3d60d64eb6dde3972ca9de338f76325b", "boringssl_crypto_tests": "8ed296da9458a249b233d884ec7a2c74fbe56c3b", "boringssl_ssl_tests": "a4326eec2bbc8835563d6bb4abe7fee2aaf43007", "browser_tests": "99727d3cee82fcfd1927e15e93eb88ba343f1609", "cacheinvalidation_unittests": "26eb11a34f57da9a2abf246039845ba8f72fdd47", "capture_unittests": "bffb4c1c9c5f890576e6f77d35a45bb637438756", "cast_unittests": "6bd2524dcf68198b1313b394cb3f8f299cc88ce4", "cc_unittests": "9565b45514699c5fc05471a854ea06d31c54173a", "chrome_app_unittests": "5a48a2e30fe958a44a8fa98b0e6b1977c84e7e7f", "chromedriver_unittests": "15fdf9f3c582ed26e8fd30318df3d82459455274", "chromeos_components_unittests": "47a36331945a75c288436520a9bbf452675d7165", "chromeos_unittests": "d45f2b5fb6d312ad99957ebe82bdcc71a44a79fb", "components_browsertests": "66505cd0e83c70434c54bd5d2ac4345cff14c0b2", "components_unittests": "a4de17137c0d9b2a7e2c133835c3ec06a383a054", "compositor_unittests": "6071f780b1e0776b87b9998f5757953f5b124199", "content_browsertests": "9703f6ffc96540eb1d309aea9a43cfed79c1d2ff", "content_unittests": "a19c55902c23646cd1902fb674f36c56b9099a7b", "crypto_unittests": "dc61523e2da78e5e3865f8c03745e26630cfb2de", "dbus_unittests": "7b013593eb0e3f6907797ff355c239fba715709c", "device_unittests": "78da84d8557b2eeed4cebc8f46d6dd89e7ba4a49", "display_unittests": "e7e20dae68e9ffb75e00d239fdaf9b2ec137481c", "events_unittests": "acc9f6c8f34fa796a0766f6267c88ee00d4f71f7", "exo_unittests": "c604ffa0540d8ff736396417b0550aee55483c06", "extensions_browsertests": "8b635d8bf7a5a567c93f7648df25fea89921655a", "extensions_unittests": "c170dec454779ba0e124f56d048e3e7e9283f6f7", "filesystem_service_unittests": "e1746e4927ad2c136033a0f1ac64e4fb3bc0fe03", "gcm_unit_tests": "446264c5193fbc28322314b8be3463d39653c92a", "gfx_unittests": "b0d8752f97bc13bb0f95fde7e65cb59fc5d910ef", "gin_unittests": "af15a210bb7c9153f8464b8029a46b3eb9fcb600", "google_apis_unittests": "90b841b69dbe7d966432a089d7b3627fb54ef078", "gpu_unittests": "009e6220ece2c3f9c043a21d205a4fd60f7268b5", "interactive_ui_tests": "14e5cfd3e71748aa3d5e0d6e8847b165db74893f", "ipc_tests": "c45361febd0e07a60e42aa6c4b7718d2750c9362", "jingle_unittests": "e64947b30eae559fdf3cb4ba1ea12d2a9c22da2e", "keyboard_unittests": "2645c8d6574f077cab7e5c97b0c9b180655d0255", "latency_unittests": "99e3d7098a7f4608f74bfee0056f617250ea095f", "leveldb_service_unittests": "cb8dd4976b4ea9559dbd20cc13792bda0c7299f4", "libjingle_xmpp_unittests": "0200181537eeab3d725bb79beca8b2ce0009c12d", "media_blink_unittests": "3299f8f7b2d8c018b46946e265bbe84778383c71", "media_service_unittests": "546736fe867aada5d9f87d73262b0f0b54313500", "media_unittests": "610c2a0d368840a1f18f81b75ac26759aa7505c1", "message_center_unittests": "de1ca4f9764710310a0b830bb8a4f32ef185fc0f", "midi_unittests": "f39508e7bbfa64eb85dcd5d574eeac09ba3b0e61", "mojo_core_unittests": "de7aaeffadcb1a9c67e2deb5cb5df0a6553ada51", "mojo_unittests": "37680db7fde79a04370e560cf0ecc6172e515f50", "nacl_helper_nonsfi_unittests": "5662230fb325b915ae13bdc32e1e245886751f38", "nacl_loader_unittests": "359fb99e32700baa996f88023774c0a77f41e77b", "native_theme_unittests": "ad74f3ff4657247e2d09d693cef2d00132581dc6", "net_unittests": "6101a7c65994259547f724500701ef44b4219941", "ozone_gl_unittests": "0a26be0d420e99daedcfda726dc58e7dfaf4790f", "ozone_unittests": "87d00bbe11ed1ce6acabbfe29bf27455e90edc6d", "ozone_x11_unittests": "c4642eb7bf276f1f4cad532d706fa68b42889269", "pdf_unittests": "0ce52596a8e994194363b5874cccb39b6a680726", "ppapi_unittests": "4886f144adcc9f64b43ed05517cce63d2023bd4f", "printing_unittests": "1f160dc72793167fe0e6242b2295c960179169e4", "remoting_unittests": "60df526f3b416301d4623b8055b2e807d2caf62b", "sandbox_linux_unittests": "bef5eab721804ec7fd185ef9253fb7e026d45626", "service_manager_unittests": "9409cc2b98aed18f2d44f192acb9b5cb2f180716", "shell_dialogs_unittests": "698aef2d5db64d6bf57fb4d8a4514b1b7d4f0170", "skia_unittests": "a11ae40bab8a2d11dc4c55b21c794364c6c62d44", "snapshot_unittests": "431a7c5a79fd17f81335dd35882e78b8a5d93f2b", "sql_unittests": "643df51f01c4a4daf208dc355a860174693eaec5", "storage_unittests": "cbe22c79d0d7290c822f03ee4dcdda90abff55fd", "sync_integration_tests": "6c9690aa5038db40259d53ab9a9bef18216a5677", "traffic_annotation_auditor_unittests": "9926ad158e1902d58281f6e0c53b8840ed663313", "ui_base_unittests": "f22d951e45ee62e1991de3f38cf6602221ec6e68", "ui_chromeos_unittests": "f31d765397198f6352e73a2dad214a37ff7fc01a", "ui_touch_selection_unittests": "1b19d833968815b61b6048e4c8ff0550795b473b", "unit_tests": "9df90e8a009d7e6f92729f574faa2d037e9a4f8a", "url_unittests": "bfeff0c5df5e3691e816bd8845135615e1a6256b", "usage_time_limit_unittests": "84c89273b65718cb89b124c71c384e6054f3319c", "views_unittests": "174830fe2afb874e36a35084a9a1fceace1b10cc", "viz_unittests": "6cf8d8a6875f95047d9622272f045f149650b7b1", "wayland_client_perftests": "3d9a1916dcd3709612ba7495f069c84cadbd0250", "wm_unittests": "9fd8a71f431d0842327f4168ca2a8220e2c71404", "wtf_unittests": "306fcdd994ab596d998968f109b00602c0cb6618"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp0rkFsY.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpffYNcU', '-o', '/b/swarming/w/ir/tmp/t/tmpbww3bw.json', '/b/swarming/w/ir/tmp/t/tmpffYNcU/43a9f7dcde48e810/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": 1552918168087415, "id": "8918640994938152752", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ChromiumOS MSan Tests/11867", "builder:Linux ChromiumOS MSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/532a82810a40d3bbdbe66eafc6de66ec01252210", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ChromiumOS MSan Builder", "parent_buildnumber:12036", "scheduler_invocation_id:9084071057514182576", "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": 11867, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "991ab98f113f5f51ec87d767b45523b19cd15b9e", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "got_revision_cp": "refs/heads/master@{#641568}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "got_webrtc_revision": "df644be3536b61256ab9e22bb0891a8b6a1d01c2", "got_webrtc_revision_cp": "refs/heads/master@{#27155}", "mastername": "chromium.memory", "parent_buildername": "Linux ChromiumOS MSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "991ab98f113f5f51ec87d767b45523b19cd15b9e", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "parent_got_revision_cp": "refs/heads/master@{#641568}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "parent_got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "parent_got_webrtc_revision": "df644be3536b61256ab9e22bb0891a8b6a1d01c2", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27155}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "532a82810a40d3bbdbe66eafc6de66ec01252210", "swarm_hashes": {"accessibility_unittests": "77657a56215abce527f179cee0b495540928de3c", "angle_unittests": "b70d85c9f3906f94924eb11e9d5b122cab28d065", "app_list_unittests": "35164ac5e91cd2b46f73d4ba283d5c84914334bc", "app_shell_unittests": "bf5d079a569b62e3a5fe40faaa54ce7be94804d2", "ash_unittests": "92e721e6e6dc9a022238e9af36714397aaecfda6", "aura_unittests": "e7830d3a8705864888ad19b3bbc249aac7973950", "base_unittests": "0f9cb3c1577a282cc56e069a09eaa43185b710ef", "blink_common_unittests": "7117068b032ea3df34fbdc432a4fef66bc8f1a26", "blink_fuzzer_unittests": "7659fef36aa2db42cdfedf8a5d58dcbad19a9f14", "blink_heap_unittests": "688ab4072e0d5c14218d893d71ff8d01f41d71ba", "blink_platform_unittests": "df2391e47f99216ba7179ede45f711dca1968231", "blink_unittests": "b0c9e25c3d60d64eb6dde3972ca9de338f76325b", "boringssl_crypto_tests": "8ed296da9458a249b233d884ec7a2c74fbe56c3b", "boringssl_ssl_tests": "a4326eec2bbc8835563d6bb4abe7fee2aaf43007", "browser_tests": "99727d3cee82fcfd1927e15e93eb88ba343f1609", "cacheinvalidation_unittests": "26eb11a34f57da9a2abf246039845ba8f72fdd47", "capture_unittests": "bffb4c1c9c5f890576e6f77d35a45bb637438756", "cast_unittests": "6bd2524dcf68198b1313b394cb3f8f299cc88ce4", "cc_unittests": "9565b45514699c5fc05471a854ea06d31c54173a", "chrome_app_unittests": "5a48a2e30fe958a44a8fa98b0e6b1977c84e7e7f", "chromedriver_unittests": "15fdf9f3c582ed26e8fd30318df3d82459455274", "chromeos_components_unittests": "47a36331945a75c288436520a9bbf452675d7165", "chromeos_unittests": "d45f2b5fb6d312ad99957ebe82bdcc71a44a79fb", "components_browsertests": "66505cd0e83c70434c54bd5d2ac4345cff14c0b2", "components_unittests": "a4de17137c0d9b2a7e2c133835c3ec06a383a054", "compositor_unittests": "6071f780b1e0776b87b9998f5757953f5b124199", "content_browsertests": "9703f6ffc96540eb1d309aea9a43cfed79c1d2ff", "content_unittests": "a19c55902c23646cd1902fb674f36c56b9099a7b", "crypto_unittests": "dc61523e2da78e5e3865f8c03745e26630cfb2de", "dbus_unittests": "7b013593eb0e3f6907797ff355c239fba715709c", "device_unittests": "78da84d8557b2eeed4cebc8f46d6dd89e7ba4a49", "display_unittests": "e7e20dae68e9ffb75e00d239fdaf9b2ec137481c", "events_unittests": "acc9f6c8f34fa796a0766f6267c88ee00d4f71f7", "exo_unittests": "c604ffa0540d8ff736396417b0550aee55483c06", "extensions_browsertests": "8b635d8bf7a5a567c93f7648df25fea89921655a", "extensions_unittests": "c170dec454779ba0e124f56d048e3e7e9283f6f7", "filesystem_service_unittests": "e1746e4927ad2c136033a0f1ac64e4fb3bc0fe03", "gcm_unit_tests": "446264c5193fbc28322314b8be3463d39653c92a", "gfx_unittests": "b0d8752f97bc13bb0f95fde7e65cb59fc5d910ef", "gin_unittests": "af15a210bb7c9153f8464b8029a46b3eb9fcb600", "google_apis_unittests": "90b841b69dbe7d966432a089d7b3627fb54ef078", "gpu_unittests": "009e6220ece2c3f9c043a21d205a4fd60f7268b5", "interactive_ui_tests": "14e5cfd3e71748aa3d5e0d6e8847b165db74893f", "ipc_tests": "c45361febd0e07a60e42aa6c4b7718d2750c9362", "jingle_unittests": "e64947b30eae559fdf3cb4ba1ea12d2a9c22da2e", "keyboard_unittests": "2645c8d6574f077cab7e5c97b0c9b180655d0255", "latency_unittests": "99e3d7098a7f4608f74bfee0056f617250ea095f", "leveldb_service_unittests": "cb8dd4976b4ea9559dbd20cc13792bda0c7299f4", "libjingle_xmpp_unittests": "0200181537eeab3d725bb79beca8b2ce0009c12d", "media_blink_unittests": "3299f8f7b2d8c018b46946e265bbe84778383c71", "media_service_unittests": "546736fe867aada5d9f87d73262b0f0b54313500", "media_unittests": "610c2a0d368840a1f18f81b75ac26759aa7505c1", "message_center_unittests": "de1ca4f9764710310a0b830bb8a4f32ef185fc0f", "midi_unittests": "f39508e7bbfa64eb85dcd5d574eeac09ba3b0e61", "mojo_core_unittests": "de7aaeffadcb1a9c67e2deb5cb5df0a6553ada51", "mojo_unittests": "37680db7fde79a04370e560cf0ecc6172e515f50", "nacl_helper_nonsfi_unittests": "5662230fb325b915ae13bdc32e1e245886751f38", "nacl_loader_unittests": "359fb99e32700baa996f88023774c0a77f41e77b", "native_theme_unittests": "ad74f3ff4657247e2d09d693cef2d00132581dc6", "net_unittests": "6101a7c65994259547f724500701ef44b4219941", "ozone_gl_unittests": "0a26be0d420e99daedcfda726dc58e7dfaf4790f", "ozone_unittests": "87d00bbe11ed1ce6acabbfe29bf27455e90edc6d", "ozone_x11_unittests": "c4642eb7bf276f1f4cad532d706fa68b42889269", "pdf_unittests": "0ce52596a8e994194363b5874cccb39b6a680726", "ppapi_unittests": "4886f144adcc9f64b43ed05517cce63d2023bd4f", "printing_unittests": "1f160dc72793167fe0e6242b2295c960179169e4", "remoting_unittests": "60df526f3b416301d4623b8055b2e807d2caf62b", "sandbox_linux_unittests": "bef5eab721804ec7fd185ef9253fb7e026d45626", "service_manager_unittests": "9409cc2b98aed18f2d44f192acb9b5cb2f180716", "shell_dialogs_unittests": "698aef2d5db64d6bf57fb4d8a4514b1b7d4f0170", "skia_unittests": "a11ae40bab8a2d11dc4c55b21c794364c6c62d44", "snapshot_unittests": "431a7c5a79fd17f81335dd35882e78b8a5d93f2b", "sql_unittests": "643df51f01c4a4daf208dc355a860174693eaec5", "storage_unittests": "cbe22c79d0d7290c822f03ee4dcdda90abff55fd", "sync_integration_tests": "6c9690aa5038db40259d53ab9a9bef18216a5677", "traffic_annotation_auditor_unittests": "9926ad158e1902d58281f6e0c53b8840ed663313", "ui_base_unittests": "f22d951e45ee62e1991de3f38cf6602221ec6e68", "ui_chromeos_unittests": "f31d765397198f6352e73a2dad214a37ff7fc01a", "ui_touch_selection_unittests": "1b19d833968815b61b6048e4c8ff0550795b473b", "unit_tests": "9df90e8a009d7e6f92729f574faa2d037e9a4f8a", "url_unittests": "bfeff0c5df5e3691e816bd8845135615e1a6256b", "usage_time_limit_unittests": "84c89273b65718cb89b124c71c384e6054f3319c", "views_unittests": "174830fe2afb874e36a35084a9a1fceace1b10cc", "viz_unittests": "6cf8d8a6875f95047d9622272f045f149650b7b1", "wayland_client_perftests": "3d9a1916dcd3709612ba7495f069c84cadbd0250", "wm_unittests": "9fd8a71f431d0842327f4168ca2a8220e2c71404", "wtf_unittests": "306fcdd994ab596d998968f109b00602c0cb6618"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp0rkFsY.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpffYNcU', '-o', '/b/swarming/w/ir/tmp/t/tmpbww3bw.json', '/b/swarming/w/ir/tmp/t/tmpffYNcU/43a9f7dcde48e810/output.json'] returned exit code 0