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/tmpByEeX3.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpV3iUpW --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/tmp4OMw6Emerge_script_log --merge-additional-args '[]' --build-properties '{"bot_id": "swarm594-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552888211363314, "id": "8918672406840449088", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ASan LSan Tests (1)/58435", "builder:Linux ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ASan LSan Builder", "parent_buildnumber:69536", "scheduler_invocation_id:9084102468832875584", "scheduler_job_id:chromium/Linux ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ASan LSan Tests (1)", "buildnumber": 58435, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "931311700c7c4b76a15c23eee8792dda125fb97e", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "got_revision_cp": "refs/heads/master@{#641522}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "got_webrtc_revision": "69008a87185992aa348ece3f893f6a84f8786ae8", "got_webrtc_revision_cp": "refs/heads/master@{#27145}", "mastername": "chromium.memory", "parent_buildername": "Linux ASan LSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "931311700c7c4b76a15c23eee8792dda125fb97e", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "parent_got_revision_cp": "refs/heads/master@{#641522}", "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": "69008a87185992aa348ece3f893f6a84f8786ae8", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27145}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "swarm_hashes": {"accessibility_unittests": "b93ce36bda8e63d0c3db86e3a8511ba873be70c3", "angle_unittests": "0af575e13122abb81d81d60250bb47e80545adac", "app_shell_unittests": "57a042252d33fb75475093e862db590904ca92ee", "aura_unittests": "2f4942a7227e10f8dd32cf75b768d0d8ce95c694", "base_unittests": "b7f824a4b2b21449edcad45705e193a59e6374d5", "blink_common_unittests": "71e2cee3cf16e2c865e2a0c7ee3d2b8b2eafaa79", "blink_fuzzer_unittests": "1520479d18bcf4a3cdadacb47885ab6898f4e4ff", "blink_heap_unittests": "4614721b4b122e97f648bcc158b13368aa84d18a", "blink_platform_unittests": "a5d37f9d592084c222ed29c4061bbb870ed5f696", "blink_unittests": "4b8a48790e4100cf28728831a58802d612c46975", "boringssl_crypto_tests": "e6886e6ca7b6e7e3be01afd2a59dc54577ec2692", "boringssl_ssl_tests": "fbf83af7ac2a5431bf30d777d49b56c55f2dc8fa", "browser_tests": "0041228e326cd756f4db8c53276fb89808703989", "cacheinvalidation_unittests": "2140fcf91e5897baf25cc0b3270375ea82fcb728", "capture_unittests": "0a5fe24da2021b333d19e905a20840c7a6975eeb", "cast_unittests": "b9c431df4e57d1f75a2ba7dfb49340bae27d12ed", "cc_unittests": "7afa1fc822a39c00ca574042dd3d445945c9594d", "chrome_app_unittests": "87195eccbb5719b0779b7375e815e53fa4a539ff", "chromedriver_unittests": "de5280689ec518c8783c6ecb4f6bec5b7952549b", "components_browsertests": "fbd614f9d47abfbc8c9537d36eb9b772fed284ce", "components_unittests": "1722a7cd5acff614d4d04e4d7b43e6b7c32e5c16", "compositor_unittests": "eada63e5e81fa7b3159865a92c45f8437ffe8bb9", "content_browsertests": "0dbf82340328ee3921157f9ce91e89d8044879fb", "content_unittests": "0236cc9195f1446deb679e75ccfe3f225e13e271", "cronet_tests": "0c3d059ff37f5f811676a3b3237018360c37bd08", "cronet_unittests": "a879e2695bc7c6706c0d88e443a2185315805c34", "crypto_unittests": "4c19cc69455f6e992bf49eb23c5f2e335d5fe63c", "dbus_unittests": "4aba2723e8a194be3e87193f7dde9c8b2a202b3d", "device_unittests": "2c6a22238da99d9f47efc46f1fb7f3c6f5d9847c", "display_unittests": "25ea0a46f20fcfae3a4b2d72ac49003ef9bc07c3", "events_unittests": "9fd456692a24299acdcf42eadb7d196ad5b512f5", "extensions_browsertests": "54e3b202c1d8e857c143a02d16e2b6556dd962c2", "extensions_unittests": "646bd2a67710cfa8a25e983223bc5f0866c95c6f", "filesystem_service_unittests": "2872f5a63ce20307eb6ab213ff89b4593b824466", "gcm_unit_tests": "71eb0428b8e07348b75336fd1bc790ae896b37ba", "gfx_unittests": "50e968dff9f430a2fd513bcd82b2766cfa0d0a0f", "gl_tests": "f986ac09446c64d213b1d5521b843d8481065297", "gl_unittests": "70b2052fee0da1da6c5aac4a0fe3fb46d192dcfc", "google_apis_unittests": "7dd42f76e0967186ac8d0d83b5615a75de030361", "gpu_unittests": "d407f194039e2dcb550749618deb0f0c609c5d67", "headless_browsertests": "5858412c39c6beb2893b084425b30dbde37a970c", "headless_unittests": "011e5958eb5070fd01d01afff4c9ca795767819c", "interactive_ui_tests": "23cdfdccc97f9035b454903a9596b829b94a9386", "ipc_tests": "7cb79d0d5c80aec55f0c2271552211dd1dcdd298", "jingle_unittests": "3e70873cf602ab532d1d67d93eb617ba6a3ff0a4", "latency_unittests": "d5f118c3a418346558365d9c508568df5a0ab111", "leveldb_service_unittests": "51b36762ae696d4633ba02bd97b823515d9fdda9", "libjingle_xmpp_unittests": "57a7f9d96bcd356c8943a6a9397d5abc1158496a", "media_blink_unittests": "7eb9745a4fdaa97fd9f8de771add01b7f7e56a70", "media_service_unittests": "33b0efaeb4bb1bf80d2b920f2968374522ead2c1", "media_unittests": "00d6b751d2ebef58492d6ad4a504f22d916b0d3d", "message_center_unittests": "253e7ed6fa4053b954455c2969e2ca42963ace6f", "midi_unittests": "a768d190fc425a6abfb2ac961d9d575643b69308", "mojo_core_unittests": "621f7f3d700d0f27049c15f6de21535e41e38c9c", "mojo_unittests": "c4b7802532809ec390a8a44ff1dd50ba6aa20920", "nacl_helper_nonsfi_unittests": "17462eb9f3e57ea3f538e034542d3e330fef8294", "nacl_loader_unittests": "6cc7c87856aaa47a095bf117f6406ef5b5cb5f0f", "native_theme_unittests": "630815d99794873fb6a94f68581009c010ea30a0", "net_unittests": "8b46341b55b90832a2bc6465205b4ccd59661251", "pdf_unittests": "86b7517e5cf1df00c077a4b12c21de31c0bebd8a", "ppapi_unittests": "8fc08723bf5c36732d0be627dd516d4ff0946854", "printing_unittests": "53899a805f2ce13c628d8e3109a00bf13b10c4ba", "remoting_unittests": "a1d1f078636f862918ecba862085e6e187d4190b", "sandbox_linux_unittests": "394822e9e6898ad28d5d05db7b39acff95389dd4", "service_manager_unittests": "14643576039d745ae53e7ebf56fd8beaf6a71cd0", "services_unittests": "efd7c9e243d7634fe08af07aa664f5ce3504d3dd", "shell_dialogs_unittests": "3596d68cf87afaa58078b069084e3e8d6cb4e904", "skia_unittests": "1201a78c4ab2349b059f5abeb488a995635b82ac", "snapshot_unittests": "e8c2d96e05befd34316cb2958367ca6d817d6cf7", "sql_unittests": "8a99a08e32e73cd2d359554b7ac6efa3bf372f18", "storage_unittests": "fe84d00a1821a5eff281de91df4478118a087430", "sync_integration_tests": "f61d6e99a591b452e0327f6b79a7d74ca4dd90bb", "traffic_annotation_auditor_unittests": "90c980e0dfd090d010df1e93eef20b67f51eda29", "ui_base_unittests": "6e2a605acca67a96cc8c53e1f2fc7f3fc39cb254", "ui_touch_selection_unittests": "e4d43769343933032cd703ad4acd7c3dd3470c4e", "unit_tests": "7d43e8898d90761f7c92ce6c11c1014d922b9070", "url_unittests": "a65e41ee14224dd132baa0b124dcaef033789555", "views_unittests": "cad6aac646b0dac1871e4ed27a161e99aed30b30", "viz_unittests": "6c7d58343a3ec826769e1f3186805dc232a695c9", "vr_common_unittests": "433418846d79e098393cc8103a0eabd8d3682f34", "vr_pixeltests": "50cff0389f600a4d5fe7c4539ef877d2e215041e", "wm_unittests": "c5c458768f71ebde213123b957033314874d9115", "wtf_unittests": "15e99f0d3c33cba3f23abc84135781df4172aa4a"}}' --summary-json-file /b/swarming/w/ir/tmp/t/tmp7c2Oyr.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/tmpDPd61v.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/tmpByEeX3.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpV3iUpW', '--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/tmp4OMw6Emerge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"bot_id": "swarm594-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552888211363314, "id": "8918672406840449088", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ASan LSan Tests (1)/58435", "builder:Linux ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ASan LSan Builder", "parent_buildnumber:69536", "scheduler_invocation_id:9084102468832875584", "scheduler_job_id:chromium/Linux ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ASan LSan Tests (1)", "buildnumber": 58435, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "931311700c7c4b76a15c23eee8792dda125fb97e", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "got_revision_cp": "refs/heads/master@{#641522}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "got_webrtc_revision": "69008a87185992aa348ece3f893f6a84f8786ae8", "got_webrtc_revision_cp": "refs/heads/master@{#27145}", "mastername": "chromium.memory", "parent_buildername": "Linux ASan LSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "931311700c7c4b76a15c23eee8792dda125fb97e", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "parent_got_revision_cp": "refs/heads/master@{#641522}", "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": "69008a87185992aa348ece3f893f6a84f8786ae8", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27145}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "swarm_hashes": {"accessibility_unittests": "b93ce36bda8e63d0c3db86e3a8511ba873be70c3", "angle_unittests": "0af575e13122abb81d81d60250bb47e80545adac", "app_shell_unittests": "57a042252d33fb75475093e862db590904ca92ee", "aura_unittests": "2f4942a7227e10f8dd32cf75b768d0d8ce95c694", "base_unittests": "b7f824a4b2b21449edcad45705e193a59e6374d5", "blink_common_unittests": "71e2cee3cf16e2c865e2a0c7ee3d2b8b2eafaa79", "blink_fuzzer_unittests": "1520479d18bcf4a3cdadacb47885ab6898f4e4ff", "blink_heap_unittests": "4614721b4b122e97f648bcc158b13368aa84d18a", "blink_platform_unittests": "a5d37f9d592084c222ed29c4061bbb870ed5f696", "blink_unittests": "4b8a48790e4100cf28728831a58802d612c46975", "boringssl_crypto_tests": "e6886e6ca7b6e7e3be01afd2a59dc54577ec2692", "boringssl_ssl_tests": "fbf83af7ac2a5431bf30d777d49b56c55f2dc8fa", "browser_tests": "0041228e326cd756f4db8c53276fb89808703989", "cacheinvalidation_unittests": "2140fcf91e5897baf25cc0b3270375ea82fcb728", "capture_unittests": "0a5fe24da2021b333d19e905a20840c7a6975eeb", "cast_unittests": "b9c431df4e57d1f75a2ba7dfb49340bae27d12ed", "cc_unittests": "7afa1fc822a39c00ca574042dd3d445945c9594d", "chrome_app_unittests": "87195eccbb5719b0779b7375e815e53fa4a539ff", "chromedriver_unittests": "de5280689ec518c8783c6ecb4f6bec5b7952549b", "components_browsertests": "fbd614f9d47abfbc8c9537d36eb9b772fed284ce", "components_unittests": "1722a7cd5acff614d4d04e4d7b43e6b7c32e5c16", "compositor_unittests": "eada63e5e81fa7b3159865a92c45f8437ffe8bb9", "content_browsertests": "0dbf82340328ee3921157f9ce91e89d8044879fb", "content_unittests": "0236cc9195f1446deb679e75ccfe3f225e13e271", "cronet_tests": "0c3d059ff37f5f811676a3b3237018360c37bd08", "cronet_unittests": "a879e2695bc7c6706c0d88e443a2185315805c34", "crypto_unittests": "4c19cc69455f6e992bf49eb23c5f2e335d5fe63c", "dbus_unittests": "4aba2723e8a194be3e87193f7dde9c8b2a202b3d", "device_unittests": "2c6a22238da99d9f47efc46f1fb7f3c6f5d9847c", "display_unittests": "25ea0a46f20fcfae3a4b2d72ac49003ef9bc07c3", "events_unittests": "9fd456692a24299acdcf42eadb7d196ad5b512f5", "extensions_browsertests": "54e3b202c1d8e857c143a02d16e2b6556dd962c2", "extensions_unittests": "646bd2a67710cfa8a25e983223bc5f0866c95c6f", "filesystem_service_unittests": "2872f5a63ce20307eb6ab213ff89b4593b824466", "gcm_unit_tests": "71eb0428b8e07348b75336fd1bc790ae896b37ba", "gfx_unittests": "50e968dff9f430a2fd513bcd82b2766cfa0d0a0f", "gl_tests": "f986ac09446c64d213b1d5521b843d8481065297", "gl_unittests": "70b2052fee0da1da6c5aac4a0fe3fb46d192dcfc", "google_apis_unittests": "7dd42f76e0967186ac8d0d83b5615a75de030361", "gpu_unittests": "d407f194039e2dcb550749618deb0f0c609c5d67", "headless_browsertests": "5858412c39c6beb2893b084425b30dbde37a970c", "headless_unittests": "011e5958eb5070fd01d01afff4c9ca795767819c", "interactive_ui_tests": "23cdfdccc97f9035b454903a9596b829b94a9386", "ipc_tests": "7cb79d0d5c80aec55f0c2271552211dd1dcdd298", "jingle_unittests": "3e70873cf602ab532d1d67d93eb617ba6a3ff0a4", "latency_unittests": "d5f118c3a418346558365d9c508568df5a0ab111", "leveldb_service_unittests": "51b36762ae696d4633ba02bd97b823515d9fdda9", "libjingle_xmpp_unittests": "57a7f9d96bcd356c8943a6a9397d5abc1158496a", "media_blink_unittests": "7eb9745a4fdaa97fd9f8de771add01b7f7e56a70", "media_service_unittests": "33b0efaeb4bb1bf80d2b920f2968374522ead2c1", "media_unittests": "00d6b751d2ebef58492d6ad4a504f22d916b0d3d", "message_center_unittests": "253e7ed6fa4053b954455c2969e2ca42963ace6f", "midi_unittests": "a768d190fc425a6abfb2ac961d9d575643b69308", "mojo_core_unittests": "621f7f3d700d0f27049c15f6de21535e41e38c9c", "mojo_unittests": "c4b7802532809ec390a8a44ff1dd50ba6aa20920", "nacl_helper_nonsfi_unittests": "17462eb9f3e57ea3f538e034542d3e330fef8294", "nacl_loader_unittests": "6cc7c87856aaa47a095bf117f6406ef5b5cb5f0f", "native_theme_unittests": "630815d99794873fb6a94f68581009c010ea30a0", "net_unittests": "8b46341b55b90832a2bc6465205b4ccd59661251", "pdf_unittests": "86b7517e5cf1df00c077a4b12c21de31c0bebd8a", "ppapi_unittests": "8fc08723bf5c36732d0be627dd516d4ff0946854", "printing_unittests": "53899a805f2ce13c628d8e3109a00bf13b10c4ba", "remoting_unittests": "a1d1f078636f862918ecba862085e6e187d4190b", "sandbox_linux_unittests": "394822e9e6898ad28d5d05db7b39acff95389dd4", "service_manager_unittests": "14643576039d745ae53e7ebf56fd8beaf6a71cd0", "services_unittests": "efd7c9e243d7634fe08af07aa664f5ce3504d3dd", "shell_dialogs_unittests": "3596d68cf87afaa58078b069084e3e8d6cb4e904", "skia_unittests": "1201a78c4ab2349b059f5abeb488a995635b82ac", "snapshot_unittests": "e8c2d96e05befd34316cb2958367ca6d817d6cf7", "sql_unittests": "8a99a08e32e73cd2d359554b7ac6efa3bf372f18", "storage_unittests": "fe84d00a1821a5eff281de91df4478118a087430", "sync_integration_tests": "f61d6e99a591b452e0327f6b79a7d74ca4dd90bb", "traffic_annotation_auditor_unittests": "90c980e0dfd090d010df1e93eef20b67f51eda29", "ui_base_unittests": "6e2a605acca67a96cc8c53e1f2fc7f3fc39cb254", "ui_touch_selection_unittests": "e4d43769343933032cd703ad4acd7c3dd3470c4e", "unit_tests": "7d43e8898d90761f7c92ce6c11c1014d922b9070", "url_unittests": "a65e41ee14224dd132baa0b124dcaef033789555", "views_unittests": "cad6aac646b0dac1871e4ed27a161e99aed30b30", "viz_unittests": "6c7d58343a3ec826769e1f3186805dc232a695c9", "vr_common_unittests": "433418846d79e098393cc8103a0eabd8d3682f34", "vr_pixeltests": "50cff0389f600a4d5fe7c4539ef877d2e215041e", "wm_unittests": "c5c458768f71ebde213123b957033314874d9115", "wtf_unittests": "15e99f0d3c33cba3f23abc84135781df4172aa4a"}}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmp7c2Oyr.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/tmpDPd61v.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: 40106 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/8918672406840449088 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/itySXjbm/luci_context.400026413 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: swarm594-c4 SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 43a82b319bb97a11 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-17 22:59:03,639 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmpV3iUpW' 2019-03-17 22:59:03,639 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmpV3iUpW' already exists! 2019-03-17 22:59:03,639 - root: [WARNING] task_output_dir existing content: [] 2019-03-17 22:59:03,639 - 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/tmpDPd61v.json -output-dir /b/swarming/w/ir/tmp/t/tmpV3iUpW -task-summary-json /b/swarming/w/ir/tmp/t/tmp7c2Oyr.json [D2019-03-17T22:59:03.648754-07:00 18497 0 auth.go:1265] Minting a new token {"key":"luci_ctx/5a0da9570e51817c4e75f4fbeb0952f27b146a4e20473b0732a9dc7878c474ce", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-17T22:59:03.648859-07:00 18497 0 luci_ctx.go:138] POST http://127.0.0.1:55599/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/5a0da9570e51817c4e75f4fbeb0952f27b146a4e20473b0732a9dc7878c474ce", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-17T22:59:03.652187-07:00 18497 0 auth.go:1222] Token expires in 57m40.348752151s {"key":"luci_ctx/5a0da9570e51817c4e75f4fbeb0952f27b146a4e20473b0732a9dc7878c474ce", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 43a82d23e0b31610: exit 0 Additional test environment: ASAN_OPTIONS=symbolize=0 handle_abort=1 CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox CHROME_HEADLESS=1 G_SLICE=always-malloc LANG=en_US.UTF-8 LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer NSS_DISABLE_ARENA_FREE_LIST=1 NSS_DISABLE_UNLOAD=1 Command: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioNGwxkY/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 [13967:13967:0315/202548.311416:6710726489:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cf0 with delay 0 [13967:13967:0315/202548.311487:6710726555:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cf0 [13967:13967:0315/202548.311830:6710726914: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 } [13967:13967:0315/202548.311913:6710726981:INFO:recurring-task.cc(55)] [Send-info] Scheduling 24104 with a delay 500000, Now = 210919424 [13967:13967:0315/202548.311950:6710727017:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001d10 with delay 500 [13967:13967:0315/202548.312046:6710727113:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001d10 [13967:13967:0315/202548.312119:6710727193:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [13967:13967:0315/202548.312165:6710727236:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (2 ms) [1/28] ProtocolHandlerTest.TokenMissing (2 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [13967:13967:0315/202548.312712:6710727781:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002290 with delay 0 [13967:13967:0315/202548.312764:6710727832:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002290 [13967:13967:0315/202548.312813:6710727883:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 29096 with a delay 500000, Now = 210919424 [13967:13967:0315/202548.312883:6710727951:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000022b0 with delay 500 [13967:13967:0315/202548.313015:6710728082:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000022b0 [13967:13967:0315/202548.313171:6710728250:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [13967:13967:0315/202548.313258:6710728324: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 } [13967:13967:0315/202548.313318:6710728389: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 } } [13967:13967:0315/202548.313494:6710728561: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 } } } [13967:13967:0315/202548.313679:6710728745: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 [13967:13967:0315/202548.314234:6710729302:INFO:protocol-handler.cc(139)] Incoming message: { } [13967:13967:0315/202548.314277:6710729345:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [13967:13967:0315/202548.314334:6710729405:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [3/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [ RUN ] RecurringTaskTest.PeriodicTask [13967:13967:0315/202548.314633:6710729700:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling 378871912 with a delay 10000, Now = 0 [13967:13967:0315/202548.314665:6710729734:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002970 with delay 10 [13967:13967:0315/202548.314718:6710729789:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002970 [13967:13967:0315/202548.314754:6710729821:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [13967:13967:0315/202548.314780:6710729849:INFO:recurring-task.cc(55)] [Retry] Scheduling 378871912 with a delay 60000, Now = 10000 [13967:13967:0315/202548.314828:6710729916:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002990 with delay 60 [13967:13967:0315/202548.314898:6710729967:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x602000002990 [13967:13967:0315/202548.314928:6710729997:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [13967:13967:0315/202548.314953:6710730020:INFO:recurring-task.cc(55)] [Retry] Scheduling 378871912 with a delay 60000, Now = 70000 [13967:13967:0315/202548.314980:6710730047:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x6020000029b0 with delay 60 [13967:13967:0315/202548.315011:6710730081:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x6020000029b0 [13967:13967:0315/202548.315045:6710730111:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [13967:13967:0315/202548.315066:6710730136:INFO:recurring-task.cc(55)] [Retry] Scheduling 378871912 with a delay 60000, Now = 130000 [13967:13967:0315/202548.315097:6710730162:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x6020000029d0 with delay 60 [13967:13967:0315/202548.315126:6710730193:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x6020000029d0 [13967:13967:0315/202548.315149:6710730214:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [13967:13967:0315/202548.315181:6710730246:INFO:recurring-task.cc(55)] [Retry] Scheduling 378871912 with a delay 60000, Now = 190000 [13967:13967:0315/202548.315206:6710730272:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x6020000029f0 with delay 60 [13967:13967:0315/202548.315233:6710730305:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x6020000029f0 [13967:13967:0315/202548.315265:6710730330:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [13967:13967:0315/202548.315292:6710730358:INFO:recurring-task.cc(55)] [Retry] Scheduling 378871912 with a delay 60000, Now = 250000 [13967:13967:0315/202548.315321:6710730387:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x602000002a10 with delay 60 [13967:13967:0315/202548.315355:6710730422:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x602000002a10 [13967:13967:0315/202548.315377:6710730443:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [13967:13967:0315/202548.315396:6710730461:INFO:recurring-task.cc(55)] [Retry] Scheduling 378871912 with a delay 60000, Now = 310000 [13967:13967:0315/202548.315414:6710730479:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x602000002a30 with delay 60 [13967:13967:0315/202548.315442:6710730512:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x602000002a30 [13967:13967:0315/202548.315467:6710730535:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [13967:13967:0315/202548.315496:6710730564:INFO:recurring-task.cc(55)] [Retry] Scheduling 378871912 with a delay 60000, Now = 370000 [13967:13967:0315/202548.315523:6710730592:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x602000002a50 with delay 60 [13967:13967:0315/202548.315568:6710730636:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x602000002a50 [13967:13967:0315/202548.315600:6710730671:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (3 ms) [4/28] RecurringTaskTest.PeriodicTask (3 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [13967:13967:0315/202548.317285:6710732356:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling 378727528 with a delay 10000, Now = 0 [13967:13967:0315/202548.317332:6710732401:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002ad0 with delay 10 [13967:13967:0315/202548.317371:6710732437:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002ad0 [13967:13967:0315/202548.317416:6710732484:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [13967:13967:0315/202548.317461:6710732528:INFO:recurring-task.cc(55)] [Retry] Scheduling 378727528 with a delay 50000, Now = 10000 [13967:13967:0315/202548.317513:6710732580:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002af0 with delay 50 [13967:13967:0315/202548.317674:6710732742:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x602000002af0 [13967:13967:0315/202548.317704:6710732771:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [13967:13967:0315/202548.317731:6710732808:INFO:recurring-task.cc(55)] [Retry] Scheduling 378727528 with a delay 149000, Now = 60000 [13967:13967:0315/202548.317783:6710732850:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x602000002b10 with delay 149 [13967:13967:0315/202548.317824:6710732890:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x602000002b10 [13967:13967:0315/202548.317859:6710732927:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [13967:13967:0315/202548.317886:6710732952:INFO:recurring-task.cc(55)] [Retry] Scheduling 378727528 with a delay 248000, Now = 210000 [13967:13967:0315/202548.317927:6710732997:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x602000002b30 with delay 248 [13967:13967:0315/202548.317978:6710733045:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x602000002b30 [13967:13967:0315/202548.318004:6710733072:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [13967:13967:0315/202548.318029:6710733098:INFO:recurring-task.cc(55)] [Retry] Scheduling 378727528 with a delay 446000, Now = 460000 [13967:13967:0315/202548.318061:6710733127:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x602000002b50 with delay 446 [13967:13967:0315/202548.318112:6710733179:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x602000002b50 [13967:13967:0315/202548.318135:6710733207:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [13967:13967:0315/202548.318170:6710733236:INFO:recurring-task.cc(55)] [Retry] Scheduling 378727528 with a delay 842000, Now = 910000 [13967:13967:0315/202548.318209:6710733277:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x602000002b70 with delay 842 [13967:13967:0315/202548.318263:6710733328:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x602000002b70 [13967:13967:0315/202548.318292:6710733358:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [13967:13967:0315/202548.318312:6710733380:INFO:recurring-task.cc(55)] [Retry] Scheduling 378727528 with a delay 1040000, Now = 1760000 [13967:13967:0315/202548.318340:6710733406:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x602000002b90 with delay 1040 [13967:13967:0315/202548.318395:6710733461:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x602000002b90 [13967:13967:0315/202548.318435:6710733505:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [13967:13967:0315/202548.318471:6710733537:INFO:recurring-task.cc(55)] [Retry] Scheduling 378727528 with a delay 1040000, Now = 2800000 [13967:13967:0315/202548.318494:6710733560:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x602000002bb0 with delay 1040 [13967:13967:0315/202548.318602:6710733668:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x602000002bb0 [13967:13967:0315/202548.318622:6710733687:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (2 ms) [5/28] RecurringTaskTest.ExponentialBackoffTask (2 ms) [ RUN ] RecurringTaskTest.OneShotTask [13967:13967:0315/202548.319677:6710734747:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling 378716264 with a delay 10000, Now = 0 [13967:13967:0315/202548.319724:6710734792:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000002c30 with delay 10 [13967:13967:0315/202548.319764:6710734831:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000002c30 [13967:13967:0315/202548.319800:6710734869:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [13967:13967:0315/202548.319832:6710734912:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling 378716264 with a delay 10000, Now = 10000 [13967:13967:0315/202548.319904:6710734971:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002c50 with delay 10 [13967:13967:0315/202548.319935:6710735004:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x602000002c50 [13967:13967:0315/202548.319971:6710735038:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (2 ms) [6/28] RecurringTaskTest.OneShotTask (2 ms) [ RUN ] ThrottleTest.ThrottlingScripted [13967:13967:0315/202548.321241:6710736314:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x602000002cd0 with delay 920 [13967:13967:0315/202548.321304:6710736370:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002cd0 [13967:13967:0315/202548.321612:6710736684:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x602000002cf0 with delay 45000 [13967:13967:0315/202548.322460:6710737529:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002cf0 [ OK ] ThrottleTest.ThrottlingScripted (1 ms) [7/28] ThrottleTest.ThrottlingScripted (1 ms) [ RUN ] ThrottleTest.ThrottlingStorm [13967:13967:0315/202548.322641:6710737714:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002d70 with delay 990 [13967:13967:0315/202548.322718:6710737784:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002d70 [13967:13967:0315/202548.322756:6710737823:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x602000002d90 with delay 1000 [13967:13967:0315/202548.322815:6710737881:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x602000002d90 [13967:13967:0315/202548.322837:6710737916:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x602000002db0 with delay 1000 [13967:13967:0315/202548.322905:6710737970:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x602000002db0 [13967:13967:0315/202548.322931:6710737996:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x602000002dd0 with delay 1000 [13967:13967:0315/202548.322986:6710738053:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x602000002dd0 [13967:13967:0315/202548.323009:6710738075:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x602000002df0 with delay 1000 [13967:13967:0315/202548.323076:6710738143:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x602000002df0 [13967:13967:0315/202548.323101:6710738169:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x602000002e10 with delay 1000 [13967:13967:0315/202548.323155:6710738220:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x602000002e10 [13967:13967:0315/202548.323186:6710738252:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x602000002e30 with delay 54000 [13967:13967:0315/202548.324860:6710739930:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002e30 [13967:13967:0315/202548.324907:6710739974:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x602000002e50 with delay 1000 [13967:13967:0315/202548.325011:6710740078:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x602000002e50 [13967:13967:0315/202548.325038:6710740105:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x602000002e70 with delay 1000 [13967:13967:0315/202548.325090:6710740155:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x602000002e70 [13967:13967:0315/202548.325134:6710740202:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x602000002e90 with delay 1000 [13967:13967:0315/202548.325189:6710740263:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x602000002e90 [13967:13967:0315/202548.325230:6710740296:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x602000002eb0 with delay 1000 [13967:13967:0315/202548.325287:6710740352:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x602000002eb0 [13967:13967:0315/202548.325311:6710740378:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x602000002ed0 with delay 1000 [13967:13967:0315/202548.325364:6710740434:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x602000002ed0 [13967:13967:0315/202548.325389:6710740455:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x602000002ef0 with delay 1000 [13967:13967:0315/202548.325461:6710740527:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x602000002ef0 [13967:13967:0315/202548.325486:6710740555:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x602000002f10 with delay 54000 [13967:13967:0315/202548.327173:6710742241:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x602000002f10 [13967:13967:0315/202548.327208:6710742275:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x602000002f30 with delay 1000 [13967:13967:0315/202548.327278:6710742347:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x602000002f30 [13967:13967:0315/202548.327318:6710742386:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x602000002f50 with delay 1000 [13967:13967:0315/202548.327377:6710742442:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x602000002f50 [13967:13967:0315/202548.327398:6710742465:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x602000002f70 with delay 1000 [13967:13967:0315/202548.327448:6710742513:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x602000002f70 [13967:13967:0315/202548.327482:6710742549:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x602000002f90 with delay 1000 [13967:13967:0315/202548.327543:6710742611:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x602000002f90 [13967:13967:0315/202548.327566:6710742632:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x602000002fb0 with delay 1000 [13967:13967:0315/202548.327622:6710742688:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x602000002fb0 [13967:13967:0315/202548.327642:6710742707:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x602000002fd0 with delay 1000 [13967:13967:0315/202548.327692:6710742759:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x602000002fd0 [13967:13967:0315/202548.327713:6710742779:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x602000002ff0 with delay 54000 [13967:13967:0315/202548.329418:6710744487:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x602000002ff0 [13967:13967:0315/202548.329473:6710744540:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x602000003010 with delay 1000 [13967:13967:0315/202548.329552:6710744617:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x602000003010 [13967:13967:0315/202548.329574:6710744639:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x602000003030 with delay 1000 [13967:13967:0315/202548.329639:6710744705:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x602000003030 [13967:13967:0315/202548.329664:6710744729:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x602000003050 with delay 1000 [13967:13967:0315/202548.329717:6710744783:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x602000003050 [13967:13967:0315/202548.329736:6710744802:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x602000003070 with delay 1000 [13967:13967:0315/202548.329793:6710744858:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x602000003070 [13967:13967:0315/202548.329863:6710744930:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x602000003090 with delay 1000 [13967:13967:0315/202548.329916:6710744982:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x602000003090 [13967:13967:0315/202548.329938:6710745006:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x6020000030b0 with delay 1000 [13967:13967:0315/202548.329995:6710745060:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x6020000030b0 [13967:13967:0315/202548.330023:6710745091:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x6020000030d0 with delay 54000 [13967:13967:0315/202548.331690:6710746760:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x6020000030d0 [13967:13967:0315/202548.331736:6710746804:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x6020000030f0 with delay 1000 [13967:13967:0315/202548.331814:6710746882:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x6020000030f0 [13967:13967:0315/202548.331854:6710746921:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x602000003110 with delay 1000 [13967:13967:0315/202548.331907:6710746973:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x602000003110 [13967:13967:0315/202548.331929:6710746994:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x602000003130 with delay 1000 [13967:13967:0315/202548.331983:6710747049:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x602000003130 [13967:13967:0315/202548.332004:6710747080:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x602000003150 with delay 1000 [13967:13967:0315/202548.332079:6710747146:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x602000003150 [13967:13967:0315/202548.332105:6710747172:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x602000003170 with delay 1000 [13967:13967:0315/202548.332157:6710747222:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x602000003170 [13967:13967:0315/202548.332201:6710747268:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x602000003190 with delay 1000 [13967:13967:0315/202548.332253:6710747318:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x602000003190 [13967:13967:0315/202548.332272:6710747338:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x6020000031b0 with delay 54000 [13967:13967:0315/202548.333996:6710749065:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x6020000031b0 [ OK ] ThrottleTest.ThrottlingStorm (12 ms) [8/28] ThrottleTest.ThrottlingStorm (12 ms) [ RUN ] ProtocolHandlerTest.SendInitializeOnly [13965:13965:0315/202548.295986:6710711058:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001cf0 with delay 0 [13965:13965:0315/202548.296620:6710711688:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001cf0 [13965:13965:0315/202548.296893:6710711964: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 } [13965:13965:0315/202548.296963:6710712032:INFO:recurring-task.cc(55)] [Startup] Scheduling 24104 with a delay 500000, Now = 210919424 [13965:13965:0315/202548.296999:6710712065:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e90 with delay 500 [13965:13965:0315/202548.297069:6710712141:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001e90 [13965:13965:0315/202548.297285:6710712357:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "unit-test-nonce" application_client_id: { client_type: 2 client_name: "unit-test-client-id" } digest_serialization_type: BYTE_BASED } } [ OK ] ProtocolHandlerTest.SendInitializeOnly (2 ms) [9/28] ProtocolHandlerTest.SendInitializeOnly (2 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [13965:13965:0315/202548.298201:6710713270: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) [10/28] ProtocolHandlerTest.ReceiveTokenControlOnly (1 ms) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes [13965:13965:0315/202548.298604:6710713673:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002ad0 with delay 0 [13965:13965:0315/202548.298658:6710713725:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002af0 with delay 0 [13965:13965:0315/202548.298694:6710713764:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b10 with delay 0 [13965:13965:0315/202548.298737:6710713805:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b30 with delay 0 [13965:13965:0315/202548.298776:6710713845:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b50 with delay 0 [13965:13965:0315/202548.298820:6710713887:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002b70 with delay 0 [13965:13965:0315/202548.299067:6710714136:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002ad0 [13965:13965:0315/202548.299177:6710714247: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 } [13965:13965:0315/202548.299233:6710714303:INFO:recurring-task.cc(55)] [Send-info] Scheduling 35624 with a delay 500000, Now = 210919424 [13965:13965:0315/202548.299268:6710714335:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002d10 with delay 500 [13965:13965:0315/202548.299296:6710714362:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002af0 [13965:13965:0315/202548.299341:6710714411:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b10 [13965:13965:0315/202548.299372:6710714441:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b30 [13965:13965:0315/202548.299399:6710714465:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b50 [13965:13965:0315/202548.299424:6710714491:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002b70 [13965:13965:0315/202548.299481:6710714554:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [13965:13965:0315/202548.299558:6710714629:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002d10 [13965:13965:0315/202548.299685:6710714752:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [13965:13965:0315/202548.300089:6710715157: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 (2 ms) [11/28] ProtocolHandlerTest.SendMultipleMessageTypes (2 ms) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage [13965:13965:0315/202548.301649:6710716718: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) [12/28] ProtocolHandlerTest.IncomingCompositeMessage (1 ms) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage [13965:13965:0315/202548.302187:6710717258: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 } } [13965:13965:0315/202548.302264:6710717330: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" } [13965:13965:0315/202548.302361:6710717428: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 } } [13965:13965:0315/202548.302450:6710717517:ERROR:protocol-handler.cc(145)] Received invalid message: { header: { client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } [ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms) [13/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch [13965:13965:0315/202548.302902:6710717970: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 } } [13965:13965:0315/202548.303035:6710718103:ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } [ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms) [14/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch [13965:13965:0315/202548.303476:6710718545:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 4 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.MinorVersionMismatch (0 ms) [15/28] ProtocolHandlerTest.MinorVersionMismatch (0 ms) [ RUN ] ProtocolHandlerTest.ConfigMessage [13965:13965:0315/202548.303920:6710718992: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" } } [13965:13965:0315/202548.303977:6710719043:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004850 with delay 0 [13965:13965:0315/202548.304001:6710719067:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004850 [13965:13965:0315/202548.304058:6710719124: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 } [13965:13965:0315/202548.304095:6710719161:INFO:recurring-task.cc(55)] [Send-info] Scheduling 66728 with a delay 500000, Now = 210919424 [13965:13965:0315/202548.304123:6710719190:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004870 with delay 500 [13965:13965:0315/202548.304192:6710719258:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004870 [13965:13965:0315/202548.304219:6710719285:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 [ OK ] ProtocolHandlerTest.ConfigMessage (46 ms) [16/28] ProtocolHandlerTest.ConfigMessage (46 ms) [ RUN ] ProtocolHandlerTest.ErrorMessage [13965:13965:0315/202548.350189:6710765265: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) [17/28] ProtocolHandlerTest.ErrorMessage (1 ms) [ RUN ] ProtocolHandlerTest.TokenMismatch [13965:13965:0315/202548.350915:6710765987:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.TokenMismatch (1 ms) [18/28] ProtocolHandlerTest.TokenMismatch (1 ms) [ RUN ] InvalidationClientImplTest.Start [13963:13963:0315/202548.288720:6710703793:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002030 with delay 0 [13963:13963:0315/202548.289537:6710704607:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13963:13963:0315/202548.289861:6710704929:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002550 with delay 0 [13963:13963:0315/202548.289901:6710704970:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002030 [13963:13963:0315/202548.289928:6710705002:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002550 [13963:13963:0315/202548.289998:6710705068:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13963:13963:0315/202548.290077:6710705145:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002610 with delay 0 [13963:13963:0315/202548.290143:6710705210:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002610 [13963:13963:0315/202548.290171:6710705242:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13963:13963:0315/202548.290206:6710705277:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002650 with delay 0 [13963:13963:0315/202548.290259:6710705325:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002650 [13963:13963:0315/202548.290285:6710705354:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13963:13963:0315/202548.290330:6710705396:INFO:recurring-task.cc(55)] [Startup] Scheduling 24360 with a delay 0, Now = 210919424 [13963:13963:0315/202548.290373:6710705441:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002670 with delay 0 [13963:13963:0315/202548.290403:6710705470:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002670 [13963:13963:0315/202548.290481:6710705550:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-7638301665308917499" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13963:13963:0315/202548.290548:6710705616:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 24616 with a delay 500000, Now = 210919424 [13963:13963:0315/202548.290596:6710705664:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002690 with delay 500 [13963:13963:0315/202548.290637:6710705706:INFO:recurring-task.cc(55)] [Retry] Scheduling 24360 with a delay 60000000, Now = 210919424 [13963:13963:0315/202548.290670:6710705737:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000026b0 with delay 60000 [13963:13963:0315/202548.290744:6710705812:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002690 [13963:13963:0315/202548.290781:6710705854:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.290884:6710705953:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.291051:6710706120: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: "-7638301665308917499" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13963:13963:0315/202548.291214:6710706281:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002750 with delay 0 [13963:13963:0315/202548.291254:6710706323:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002750 [13963:13963:0315/202548.291411:6710706482:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-7638301665308917499" 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" } } [13963:13963:0315/202548.291493:6710706568:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-7638301665308917499" [13963:13963:0315/202548.291546:6710706616:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13963:13963:0315/202548.291580:6710706646:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 13448 with a delay 1200000000, Now = 211419424 [13963:13963:0315/202548.291625:6710706696:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002770 with delay 1200000 [13963:13963:0315/202548.291679:6710706752:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13963:13963:0315/202548.291878:6710706944:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13963:13963:0315/202548.291915:6710706983:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 9672 with a delay 0, Now = 211419424 [13963:13963:0315/202548.291949:6710707018:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002990 with delay 0 [13963:13963:0315/202548.292004:6710707075: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 [13963:13963:0315/202548.292057:6710707125:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002990 [13963:13963:0315/202548.292143:6710707211:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a50 with delay 0 [13963:13963:0315/202548.292186:6710707254:INFO:recurring-task.cc(55)] [Retry] Scheduling 9672 with a delay 10000000, Now = 211419424 [13963:13963:0315/202548.292215:6710707282:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000002a90 with delay 10000 [13963:13963:0315/202548.292242:6710707308:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002a50 [13963:13963:0315/202548.292275:6710707340:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (4 ms) [19/28] InvalidationClientImplTest.Start (4 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [13963:13963:0315/202548.293031:6710708100:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000032f0 with delay 0 [13963:13963:0315/202548.293087:6710708154:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [ OK ] InvalidationClientImplTest.GenerateNonce (1 ms) [20/28] InvalidationClientImplTest.GenerateNonce (1 ms) [ RUN ] InvalidationClientImplTest.Register [13963:13963:0315/202548.293586:6710708654:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003b90 with delay 0 [13963:13963:0315/202548.293654:6710708735:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13963:13963:0315/202548.293983:6710709054:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000041f0 with delay 0 [13963:13963:0315/202548.294030:6710709096:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003b90 [13963:13963:0315/202548.294058:6710709123:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000041f0 [13963:13963:0315/202548.294105:6710709172:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13963:13963:0315/202548.294173:6710709244:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000042b0 with delay 0 [13963:13963:0315/202548.294216:6710709284:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000042b0 [13963:13963:0315/202548.294251:6710709321:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13963:13963:0315/202548.294285:6710709351:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000042f0 with delay 0 [13963:13963:0315/202548.294317:6710709383:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000042f0 [13963:13963:0315/202548.294338:6710709404:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13963:13963:0315/202548.294381:6710709447:INFO:recurring-task.cc(55)] [Startup] Scheduling 48296 with a delay 0, Now = 210919424 [13963:13963:0315/202548.294413:6710709480:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004310 with delay 0 [13963:13963:0315/202548.294441:6710709507:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004310 [13963:13963:0315/202548.294499:6710709574:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-4964784429749256792" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13963:13963:0315/202548.294559:6710709629:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 48552 with a delay 500000, Now = 210919424 [13963:13963:0315/202548.294594:6710709661:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004330 with delay 500 [13963:13963:0315/202548.294621:6710709686:INFO:recurring-task.cc(55)] [Retry] Scheduling 48296 with a delay 60000000, Now = 210919424 [13963:13963:0315/202548.294656:6710709725:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004350 with delay 60000 [13963:13963:0315/202548.294723:6710709791:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004330 [13963:13963:0315/202548.294764:6710709836:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.294826:6710709893:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.294995:6710710062: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: "-4964784429749256792" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13963:13963:0315/202548.295123:6710710191:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000043f0 with delay 0 [13963:13963:0315/202548.295162:6710710235:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000043f0 [13963:13963:0315/202548.295285:6710710353:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-4964784429749256792" 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" } } [13963:13963:0315/202548.295348:6710710416:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-4964784429749256792" [13963:13963:0315/202548.295386:6710710457:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13963:13963:0315/202548.295432:6710710500:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 15736 with a delay 1200000000, Now = 211419424 [13963:13963:0315/202548.295460:6710710526:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004410 with delay 1200000 [13963:13963:0315/202548.295504:6710710571:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13963:13963:0315/202548.295653:6710710727:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13963:13963:0315/202548.295706:6710710774:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 14088 with a delay 0, Now = 211419424 [13963:13963:0315/202548.295745:6710710812:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004630 with delay 0 [13963:13963:0315/202548.295809:6710710876: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 [13963:13963:0315/202548.295871:6710710937:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004630 [13963:13963:0315/202548.295955:6710711022:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000046f0 with delay 0 [13963:13963:0315/202548.295990:6710711056:INFO:recurring-task.cc(55)] [Retry] Scheduling 14088 with a delay 10000000, Now = 211419424 [13963:13963:0315/202548.296037:6710711111:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000004730 with delay 10000 [13963:13963:0315/202548.296076:6710711144:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000046f0 [13963:13963:0315/202548.296099:6710711172:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13963:13963:0315/202548.296185:6710711252:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004750 with delay 0 [13963:13963:0315/202548.296213:6710711279:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000004750 [13963:13963:0315/202548.296270:6710711337:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [13963:13963:0315/202548.296305:6710711372:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [13963:13963:0315/202548.296333:6710711399:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [13963:13963:0315/202548.296400:6710711469:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 48552 with a delay 500000, Now = 211469424 [13963:13963:0315/202548.296431:6710711499:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004770 with delay 500 [13963:13963:0315/202548.296469:6710711535:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 48424 with a delay 60000000, Now = 211469424 [13963:13963:0315/202548.296497:6710711567:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000004790 with delay 60000 [13963:13963:0315/202548.296574:6710711640:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000004770 [13963:13963:0315/202548.296600:6710711667:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.296666:6710711733:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.296694:6710711762:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13963:13963:0315/202548.296836:6710711918: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 } } } [13963:13963:0315/202548.296982:6710712057:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.297073:6710712141:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000004830 with delay 0 [13963:13963:0315/202548.297104:6710712171:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000004830 [13963:13963:0315/202548.297301:6710712369: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 } } } } [13963:13963:0315/202548.297399:6710712467: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 [13963:13963:0315/202548.297475:6710712542:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [13963:13963:0315/202548.297572:6710712639:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [13963:13963:0315/202548.297657:6710712725:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [13963:13963:0315/202548.298088:6710713160:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000004730 [ OK ] InvalidationClientImplTest.Register (6 ms) [21/28] InvalidationClientImplTest.Register (6 ms) [ RUN ] InvalidationClientImplTest.Invalidations [13963:13963:0315/202548.300041:6710715112:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005410 with delay 0 [13963:13963:0315/202548.300103:6710715169:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13963:13963:0315/202548.300443:6710715511:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005af0 with delay 0 [13963:13963:0315/202548.300478:6710715562:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005410 [13963:13963:0315/202548.300523:6710715590:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005af0 [13963:13963:0315/202548.300588:6710715656:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13963:13963:0315/202548.300663:6710715730:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005bb0 with delay 0 [13963:13963:0315/202548.300703:6710715771:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005bb0 [13963:13963:0315/202548.300729:6710715796:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13963:13963:0315/202548.300760:6710715827:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005bf0 with delay 0 [13963:13963:0315/202548.300796:6710715865:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005bf0 [13963:13963:0315/202548.300820:6710715885:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13963:13963:0315/202548.300859:6710715925:INFO:recurring-task.cc(55)] [Startup] Scheduling 79400 with a delay 0, Now = 210919424 [13963:13963:0315/202548.300886:6710715954:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c10 with delay 0 [13963:13963:0315/202548.300911:6710715976:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000005c10 [13963:13963:0315/202548.301018:6710716086:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-7916833557551252772" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13963:13963:0315/202548.301059:6710716127:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 79656 with a delay 500000, Now = 210919424 [13963:13963:0315/202548.301093:6710716159:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c30 with delay 500 [13963:13963:0315/202548.301119:6710716186:INFO:recurring-task.cc(55)] [Retry] Scheduling 79400 with a delay 60000000, Now = 210919424 [13963:13963:0315/202548.301144:6710716212:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000005c50 with delay 60000 [13963:13963:0315/202548.301191:6710716257:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005c30 [13963:13963:0315/202548.301222:6710716290:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.301269:6710716337:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.301382:6710716449: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: "-7916833557551252772" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13963:13963:0315/202548.301526:6710716593:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005cf0 with delay 0 [13963:13963:0315/202548.301568:6710716639:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005cf0 [13963:13963:0315/202548.301711:6710716779:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-7916833557551252772" 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" } } [13963:13963:0315/202548.301764:6710716832:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-7916833557551252772" [13963:13963:0315/202548.301798:6710716865:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13963:13963:0315/202548.301831:6710716898:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 20840 with a delay 1200000000, Now = 211419424 [13963:13963:0315/202548.301874:6710716941:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005d10 with delay 1200000 [13963:13963:0315/202548.301905:6710716971:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13963:13963:0315/202548.302019:6710717086:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13963:13963:0315/202548.302048:6710717115:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 21000 with a delay 0, Now = 211419424 [13963:13963:0315/202548.302095:6710717162:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005f30 with delay 0 [13963:13963:0315/202548.302145:6710717213: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 [13963:13963:0315/202548.302203:6710717278:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005f30 [13963:13963:0315/202548.302272:6710717339:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005ff0 with delay 0 [13963:13963:0315/202548.302319:6710717387:INFO:recurring-task.cc(55)] [Retry] Scheduling 21000 with a delay 10000000, Now = 211419424 [13963:13963:0315/202548.302347:6710717418:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000006030 with delay 10000 [13963:13963:0315/202548.302378:6710717443:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005ff0 [13963:13963:0315/202548.302399:6710717465:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13963:13963:0315/202548.302448:6710717516:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.302509:6710717576:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000006050 with delay 0 [13963:13963:0315/202548.302534:6710717600:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000006050 [13963:13963:0315/202548.302724:6710717792: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 } } } [13963:13963:0315/202548.302803:6710717870: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 [13963:13963:0315/202548.302901:6710717968: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" } [13963:13963:0315/202548.303010:6710718077:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [13963:13963:0315/202548.303086:6710718153:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [13963:13963:0315/202548.303157:6710718225:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006430 with delay 0 [13963:13963:0315/202548.303187:6710718255:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006450 with delay 0 [13963:13963:0315/202548.303220:6710718287:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006470 with delay 0 [13963:13963:0315/202548.303246:6710718313:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006430 [13963:13963:0315/202548.303298:6710718367:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 79656 with a delay 500000, Now = 211519424 [13963:13963:0315/202548.303328:6710718395:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000006490 with delay 500 [13963:13963:0315/202548.303372:6710718440:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006450 [13963:13963:0315/202548.303401:6710718467:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000006470 [13963:13963:0315/202548.303440:6710718507:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x602000006490 [13963:13963:0315/202548.303467:6710718535:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.303529:6710718613:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.303593:6710718664:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13963:13963:0315/202548.303827:6710718894:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777601100 max_known_server_time_ms: 314159265 message_id: "2" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } } } [ OK ] InvalidationClientImplTest.Invalidations (5 ms) [22/28] InvalidationClientImplTest.Invalidations (5 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [13963:13963:0315/202548.304557:6710719626:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006d70 with delay 0 [13963:13963:0315/202548.304607:6710719674:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13963:13963:0315/202548.304854:6710719924:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007290 with delay 0 [13963:13963:0315/202548.304887:6710719957:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006d70 [13963:13963:0315/202548.304925:6710719992:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007290 [13963:13963:0315/202548.305016:6710720084:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13963:13963:0315/202548.305084:6710720157:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007350 with delay 0 [13963:13963:0315/202548.305137:6710720204:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007350 [13963:13963:0315/202548.305165:6710720232:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13963:13963:0315/202548.305194:6710720262:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007390 with delay 0 [13963:13963:0315/202548.305228:6710720295:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007390 [13963:13963:0315/202548.305251:6710720317:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13963:13963:0315/202548.305293:6710720360:INFO:recurring-task.cc(55)] [Startup] Scheduling 109096 with a delay 0, Now = 210919424 [13963:13963:0315/202548.305321:6710720388:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073b0 with delay 0 [13963:13963:0315/202548.305346:6710720412:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000073b0 [13963:13963:0315/202548.305405:6710720472:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-5443678110771886437" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13963:13963:0315/202548.305440:6710720507:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 109352 with a delay 500000, Now = 210919424 [13963:13963:0315/202548.305472:6710720541:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073d0 with delay 500 [13963:13963:0315/202548.305498:6710720569:INFO:recurring-task.cc(55)] [Retry] Scheduling 109096 with a delay 60000000, Now = 210919424 [13963:13963:0315/202548.305535:6710720602:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000073f0 with delay 60000 [13963:13963:0315/202548.305590:6710720656:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000073d0 [13963:13963:0315/202548.305615:6710720681:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.305660:6710720727:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.305775:6710720843: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: "-5443678110771886437" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13963:13963:0315/202548.305879:6710720946:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007490 with delay 0 [13963:13963:0315/202548.305922:6710720990:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007490 [13963:13963:0315/202548.306025:6710721091:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-5443678110771886437" 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" } } [13963:13963:0315/202548.306073:6710721141:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-5443678110771886437" [13963:13963:0315/202548.306104:6710721172:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13963:13963:0315/202548.306152:6710721219:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 24888 with a delay 1200000000, Now = 211419424 [13963:13963:0315/202548.306179:6710721247:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000074b0 with delay 1200000 [13963:13963:0315/202548.306218:6710721286:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13963:13963:0315/202548.306329:6710721396:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13963:13963:0315/202548.306369:6710721436:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 27336 with a delay 0, Now = 211419424 [13963:13963:0315/202548.306394:6710721463:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000076d0 with delay 0 [13963:13963:0315/202548.306440:6710721507: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 [13963:13963:0315/202548.306477:6710721544:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000076d0 [13963:13963:0315/202548.306536:6710721611:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007790 with delay 0 [13963:13963:0315/202548.306578:6710721651:INFO:recurring-task.cc(55)] [Retry] Scheduling 27336 with a delay 10000000, Now = 211419424 [13963:13963:0315/202548.306624:6710721691:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000077d0 with delay 10000 [13963:13963:0315/202548.306671:6710721742:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007790 [13963:13963:0315/202548.306703:6710721772:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13963:13963:0315/202548.306759:6710721827:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.306801:6710721868:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000077f0 with delay 0 [13963:13963:0315/202548.306835:6710721920:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x6020000077f0 [13963:13963:0315/202548.306972:6710722040: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 } } [13963:13963:0315/202548.307044:6710722112: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 [13963:13963:0315/202548.307076:6710722143:INFO:protocol-handler.cc(294)] Adding subtree: { } [13963:13963:0315/202548.307106:6710722173:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 109352 with a delay 500000, Now = 211469424 [13963:13963:0315/202548.307132:6710722201:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000007810 with delay 500 [13963:13963:0315/202548.307167:6710722234:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [13963:13963:0315/202548.307353:6710722421: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 } [13963:13963:0315/202548.307429:6710722497:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000007810 [13963:13963:0315/202548.307465:6710722534:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.307532:6710722600:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.307559:6710722626:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13963:13963:0315/202548.307890:6710722958: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 } } [13963:13963:0315/202548.308293:6710723362:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x6020000077d0 [ OK ] InvalidationClientImplTest.ServerRequests (5 ms) [23/28] InvalidationClientImplTest.ServerRequests (5 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [13963:13963:0315/202548.309784:6710724853:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000080f0 with delay 0 [13963:13963:0315/202548.309832:6710724915:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13963:13963:0315/202548.310073:6710725141:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000086b0 with delay 0 [13963:13963:0315/202548.310105:6710725172:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000080f0 [13963:13963:0315/202548.310136:6710725204:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000086b0 [13963:13963:0315/202548.310189:6710725255:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13963:13963:0315/202548.310243:6710725309:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008770 with delay 0 [13963:13963:0315/202548.310277:6710725343:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008770 [13963:13963:0315/202548.310307:6710725375:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13963:13963:0315/202548.310342:6710725408:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087b0 with delay 0 [13963:13963:0315/202548.310366:6710725432:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087b0 [13963:13963:0315/202548.310388:6710725456:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13963:13963:0315/202548.310418:6710725485:INFO:recurring-task.cc(55)] [Startup] Scheduling 136488 with a delay 0, Now = 210919424 [13963:13963:0315/202548.310448:6710725515:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087d0 with delay 0 [13963:13963:0315/202548.310473:6710725541:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000087d0 [13963:13963:0315/202548.310528:6710725595:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-6506596319753811017" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13963:13963:0315/202548.310576:6710725643:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 136744 with a delay 500000, Now = 210919424 [13963:13963:0315/202548.310609:6710725676:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000087f0 with delay 500 [13963:13963:0315/202548.310634:6710725701:INFO:recurring-task.cc(55)] [Retry] Scheduling 136488 with a delay 60000000, Now = 210919424 [13963:13963:0315/202548.310660:6710725728:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008810 with delay 60000 [13963:13963:0315/202548.310696:6710725762:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000087f0 [13963:13963:0315/202548.310719:6710725786:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.310757:6710725824:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.310894:6710725961: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: "-6506596319753811017" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13963:13963:0315/202548.310994:6710726061:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000088b0 with delay 0 [13963:13963:0315/202548.311022:6710726089:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000088b0 [13963:13963:0315/202548.311132:6710726200:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-6506596319753811017" 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" } } [13963:13963:0315/202548.311180:6710726247:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-6506596319753811017" [13963:13963:0315/202548.311228:6710726294:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13963:13963:0315/202548.311258:6710726326:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 28232 with a delay 1200000000, Now = 211419424 [13963:13963:0315/202548.311297:6710726364:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000088d0 with delay 1200000 [13963:13963:0315/202548.311328:6710726394:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13963:13963:0315/202548.311446:6710726513:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13963:13963:0315/202548.311476:6710726543:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 32904 with a delay 0, Now = 211419424 [13963:13963:0315/202548.311503:6710726568:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008af0 with delay 0 [13963:13963:0315/202548.311542:6710726608: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 [13963:13963:0315/202548.311575:6710726642:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008af0 [13963:13963:0315/202548.311650:6710726717:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008bb0 with delay 0 [13963:13963:0315/202548.311687:6710726754:INFO:recurring-task.cc(55)] [Retry] Scheduling 32904 with a delay 10000000, Now = 211419424 [13963:13963:0315/202548.311714:6710726781:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000008bf0 with delay 10000 [13963:13963:0315/202548.311740:6710726807:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000008bb0 [13963:13963:0315/202548.311763:6710726829:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13963:13963:0315/202548.311801:6710726868:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.311860:6710726928:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000008c10 with delay 0 [13963:13963:0315/202548.311891:6710726957:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000008c10 [13963:13963:0315/202548.311998:6710727066: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" } } [13963:13963:0315/202548.312056:6710727123: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 [13963:13963:0315/202548.312096:6710727162:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [13963:13963:0315/202548.312375:6710727443:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000008bf0 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [24/28] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [13963:13963:0315/202548.313717:6710728787:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009570 with delay 0 [13963:13963:0315/202548.313767:6710728832:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13963:13963:0315/202548.314037:6710729105:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009bf0 with delay 0 [13963:13963:0315/202548.314068:6710729135:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009570 [13963:13963:0315/202548.314092:6710729159:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009bf0 [13963:13963:0315/202548.314151:6710729217:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13963:13963:0315/202548.314215:6710729282:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009cb0 with delay 0 [13963:13963:0315/202548.314249:6710729315:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009cb0 [13963:13963:0315/202548.314272:6710729338:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13963:13963:0315/202548.314311:6710729379:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009cf0 with delay 0 [13963:13963:0315/202548.314336:6710729401:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009cf0 [13963:13963:0315/202548.314355:6710729421:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13963:13963:0315/202548.314385:6710729452:INFO:recurring-task.cc(55)] [Startup] Scheduling 159144 with a delay 0, Now = 210919424 [13963:13963:0315/202548.314411:6710729478:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d10 with delay 0 [13963:13963:0315/202548.314434:6710729500:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009d10 [13963:13963:0315/202548.314506:6710729574:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "4608907020573242508" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13963:13963:0315/202548.314548:6710729615:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 159400 with a delay 500000, Now = 210919424 [13963:13963:0315/202548.314575:6710729644:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d30 with delay 500 [13963:13963:0315/202548.314603:6710729670:INFO:recurring-task.cc(55)] [Retry] Scheduling 159144 with a delay 60000000, Now = 210919424 [13963:13963:0315/202548.314632:6710729699:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009d50 with delay 60000 [13963:13963:0315/202548.314672:6710729738:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009d30 [13963:13963:0315/202548.314701:6710729769:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.314740:6710729807:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.314894:6710729962: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: "4608907020573242508" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13963:13963:0315/202548.314997:6710730064:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009df0 with delay 0 [13963:13963:0315/202548.315028:6710730096:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009df0 [13963:13963:0315/202548.315159:6710730227:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "4608907020573242508" 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" } } [13963:13963:0315/202548.315215:6710730283:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "4608907020573242508" [13963:13963:0315/202548.315244:6710730311:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13963:13963:0315/202548.315275:6710730343:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 31400 with a delay 1200000000, Now = 211419424 [13963:13963:0315/202548.315307:6710730375:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009e10 with delay 1200000 [13963:13963:0315/202548.315339:6710730405:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13963:13963:0315/202548.315468:6710730536:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13963:13963:0315/202548.315502:6710730570:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 36552 with a delay 0, Now = 211419424 [13963:13963:0315/202548.315530:6710730596:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a030 with delay 0 [13963:13963:0315/202548.315571:6710730639: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 [13963:13963:0315/202548.315604:6710730671:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a030 [13963:13963:0315/202548.315660:6710730727:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a0f0 with delay 0 [13963:13963:0315/202548.315693:6710730760:INFO:recurring-task.cc(55)] [Retry] Scheduling 36552 with a delay 10000000, Now = 211419424 [13963:13963:0315/202548.315722:6710730789:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a130 with delay 10000 [13963:13963:0315/202548.315753:6710730820:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a0f0 [13963:13963:0315/202548.315777:6710730843:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13963:13963:0315/202548.315828:6710730896:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a150 with delay 0 [13963:13963:0315/202548.315869:6710730936:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000a150 [13963:13963:0315/202548.315902:6710730970:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [13963:13963:0315/202548.315950:6710731017:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 159400 with a delay 500000, Now = 211469424 [13963:13963:0315/202548.315985:6710731053:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a170 with delay 500 [13963:13963:0315/202548.316014:6710731081:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 159272 with a delay 60000000, Now = 211469424 [13963:13963:0315/202548.316040:6710731107:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000a190 with delay 60000 [13963:13963:0315/202548.316086:6710731155:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000a170 [13963:13963:0315/202548.316110:6710731177:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.316149:6710731216:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.316175:6710731242:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13963:13963:0315/202548.316292:6710731359: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 } } } [13963:13963:0315/202548.316365:6710731431:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.316410:6710731477:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x60200000a230 with delay 0 [13963:13963:0315/202548.316437:6710731504:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000a230 [13963:13963:0315/202548.316546:6710731620: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" } } [13963:13963:0315/202548.316627:6710731694: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 [13963:13963:0315/202548.316656:6710731724:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [13963:13963:0315/202548.316748:6710731815:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [13963:13963:0315/202548.317093:6710732165:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000a130 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms) [25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [13963:13963:0315/202548.319099:6710734172:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ac90 with delay 0 [13963:13963:0315/202548.319194:6710734275:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13963:13963:0315/202548.319522:6710734595:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b1b0 with delay 0 [13963:13963:0315/202548.319577:6710734649:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000ac90 [13963:13963:0315/202548.319619:6710734690:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b1b0 [13963:13963:0315/202548.319703:6710734775:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13963:13963:0315/202548.319781:6710734852:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b270 with delay 0 [13963:13963:0315/202548.319831:6710734916:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b270 [13963:13963:0315/202548.319883:6710734954:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13963:13963:0315/202548.319947:6710735019:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2b0 with delay 0 [13963:13963:0315/202548.320000:6710735072:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b2b0 [13963:13963:0315/202548.320047:6710735118:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13963:13963:0315/202548.320098:6710735170:INFO:recurring-task.cc(55)] [Startup] Scheduling 187560 with a delay 0, Now = 210919424 [13963:13963:0315/202548.320148:6710735220:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2d0 with delay 0 [13963:13963:0315/202548.320190:6710735261:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b2d0 [13963:13963:0315/202548.320282:6710735353:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "5959510787952106379" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13963:13963:0315/202548.320331:6710735403:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 187816 with a delay 500000, Now = 210919424 [13963:13963:0315/202548.320379:6710735450:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b2f0 with delay 500 [13963:13963:0315/202548.320420:6710735490:INFO:recurring-task.cc(55)] [Retry] Scheduling 187560 with a delay 60000000, Now = 210919424 [13963:13963:0315/202548.320464:6710735535:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b310 with delay 60000 [13963:13963:0315/202548.320520:6710735591:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b2f0 [13963:13963:0315/202548.320572:6710735644:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.320631:6710735703:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.320819:6710735912: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: "5959510787952106379" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13963:13963:0315/202548.321032:6710736104:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b3b0 with delay 0 [13963:13963:0315/202548.321086:6710736156:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b3b0 [13963:13963:0315/202548.321250:6710736322:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "5959510787952106379" 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" } } [13963:13963:0315/202548.321331:6710736403:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "5959510787952106379" [13963:13963:0315/202548.321384:6710736456:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13963:13963:0315/202548.321435:6710736507:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 34744 with a delay 1200000000, Now = 211419424 [13963:13963:0315/202548.321479:6710736549:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b3d0 with delay 1200000 [13963:13963:0315/202548.321526:6710736599:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13963:13963:0315/202548.321720:6710736792:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13963:13963:0315/202548.321782:6710736853:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 42120 with a delay 0, Now = 211419424 [13963:13963:0315/202548.321827:6710736914:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b5f0 with delay 0 [13963:13963:0315/202548.321919:6710736993: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 [13963:13963:0315/202548.321978:6710737049:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b5f0 [13963:13963:0315/202548.322069:6710737140:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b6b0 with delay 0 [13963:13963:0315/202548.322124:6710737195:INFO:recurring-task.cc(55)] [Retry] Scheduling 42120 with a delay 10000000, Now = 211419424 [13963:13963:0315/202548.322169:6710737240:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000b6f0 with delay 10000 [13963:13963:0315/202548.322222:6710737293:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000b6b0 [13963:13963:0315/202548.322261:6710737332:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13963:13963:0315/202548.322322:6710737394:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b710 with delay 0 [13963:13963:0315/202548.322367:6710737439:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000b710 [13963:13963:0315/202548.322424:6710737496:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [13963:13963:0315/202548.322523:6710737595:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 187816 with a delay 500000, Now = 211469424 [13963:13963:0315/202548.322583:6710737656:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b730 with delay 500 [13963:13963:0315/202548.322646:6710737719:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 187688 with a delay 60000000, Now = 211469424 [13963:13963:0315/202548.322695:6710737767:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000b750 with delay 60000 [13963:13963:0315/202548.322779:6710737852:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000b730 [13963:13963:0315/202548.322822:6710737918:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.322913:6710737985:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.322963:6710738037:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13963:13963:0315/202548.323146:6710738219: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 } } } [13963:13963:0315/202548.323641:6710738713:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000b6f0 [13963:13963:0315/202548.325132:6710740206:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000b310 [13963:13963:0315/202548.325200:6710740278:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x60200000b750 [13963:13963:0315/202548.325311:6710740384: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 [13963:13963:0315/202548.325359:6710740431:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [13963:13963:0315/202548.325464:6710740536: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 } [13963:13963:0315/202548.325526:6710740597:INFO:recurring-task.cc(55)] [Send-info] Scheduling 187816 with a delay 500000, Now = 271469424 [13963:13963:0315/202548.325570:6710740641:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000b7f0 with delay 500 [13963:13963:0315/202548.325617:6710740687:INFO:recurring-task.cc(55)] [Retry] Scheduling 187688 with a delay 60000000, Now = 271469424 [13963:13963:0315/202548.325658:6710740731:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000b810 with delay 60000 [13963:13963:0315/202548.325717:6710740788:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x60200000b7f0 [13963:13963:0315/202548.325759:6710740829:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.325828:6710740899:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.325887:6710740959:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13963:13963:0315/202548.326107:6710741180: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 (9 ms) [26/28] InvalidationClientImplTest.NetworkTimeouts (9 ms) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary [13963:13963:0315/202548.328541:6710743615:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c0f0 with delay 0 [13963:13963:0315/202548.328622:6710743693:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13963:13963:0315/202548.328965:6710744041:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c610 with delay 0 [13963:13963:0315/202548.329031:6710744102:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c0f0 [13963:13963:0315/202548.329077:6710744147:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c610 [13963:13963:0315/202548.329155:6710744227:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13963:13963:0315/202548.329243:6710744315:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c6d0 with delay 0 [13963:13963:0315/202548.329291:6710744362:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c6d0 [13963:13963:0315/202548.329372:6710744443:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13963:13963:0315/202548.329416:6710744487:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c710 with delay 0 [13963:13963:0315/202548.329461:6710744532:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c710 [13963:13963:0315/202548.329499:6710744571:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13963:13963:0315/202548.329545:6710744615:INFO:recurring-task.cc(55)] [Startup] Scheduling 216488 with a delay 0, Now = 210919424 [13963:13963:0315/202548.329593:6710744664:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c730 with delay 0 [13963:13963:0315/202548.329637:6710744709:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c730 [13963:13963:0315/202548.329732:6710744805:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-8435181797054885258" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13963:13963:0315/202548.329792:6710744864:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 216744 with a delay 500000, Now = 210919424 [13963:13963:0315/202548.329854:6710744926:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c750 with delay 500 [13963:13963:0315/202548.329899:6710744969:INFO:recurring-task.cc(55)] [Retry] Scheduling 216488 with a delay 60000000, Now = 210919424 [13963:13963:0315/202548.329938:6710745009:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c770 with delay 60000 [13963:13963:0315/202548.329996:6710745066:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c750 [13963:13963:0315/202548.330035:6710745112:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.330102:6710745173:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.330301:6710745374: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: "-8435181797054885258" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13963:13963:0315/202548.330447:6710745519:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c810 with delay 0 [13963:13963:0315/202548.330496:6710745576:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000c810 [13963:13963:0315/202548.330680:6710745753:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-8435181797054885258" 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" } } [13963:13963:0315/202548.330763:6710745835:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-8435181797054885258" [13963:13963:0315/202548.330808:6710745883:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13963:13963:0315/202548.330900:6710745971:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 37384 with a delay 1200000000, Now = 211419424 [13963:13963:0315/202548.330946:6710746018:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000c830 with delay 1200000 [13963:13963:0315/202548.330996:6710746067:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13963:13963:0315/202548.331187:6710746260:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13963:13963:0315/202548.331248:6710746320:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 48456 with a delay 0, Now = 211419424 [13963:13963:0315/202548.331294:6710746365:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ca50 with delay 0 [13963:13963:0315/202548.331365:6710746436: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 [13963:13963:0315/202548.331417:6710746490:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ca50 [13963:13963:0315/202548.331537:6710746608:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000cb10 with delay 0 [13963:13963:0315/202548.331594:6710746666:INFO:recurring-task.cc(55)] [Retry] Scheduling 48456 with a delay 10000000, Now = 211419424 [13963:13963:0315/202548.331647:6710746718:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000cb50 with delay 10000 [13963:13963:0315/202548.331687:6710746757:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000cb10 [13963:13963:0315/202548.331726:6710746797:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13963:13963:0315/202548.331796:6710746869:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.331872:6710746947:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000cb70 with delay 0 [13963:13963:0315/202548.331917:6710746989:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000cb70 [13963:13963:0315/202548.332048:6710747122: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" } } [13963:13963:0315/202548.332455:6710747533:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000cb50 [13963:13963:0315/202548.333751:6710748824: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 (6 ms) [27/28] InvalidationClientImplTest.NoRegistrationSummary (6 ms) [ RUN ] InvalidationClientImplTest.Heartbeats [13963:13963:0315/202548.334678:6710749752:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d3d0 with delay 0 [13963:13963:0315/202548.334765:6710749837:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [13963:13963:0315/202548.335054:6710750136:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d8f0 with delay 0 [13963:13963:0315/202548.335121:6710750194:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d3d0 [13963:13963:0315/202548.335194:6710750273:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d8f0 [13963:13963:0315/202548.335293:6710750365:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [13963:13963:0315/202548.335375:6710750447:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d9b0 with delay 0 [13963:13963:0315/202548.335427:6710750500:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d9b0 [13963:13963:0315/202548.335467:6710750538:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [13963:13963:0315/202548.335515:6710750587:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000d9f0 with delay 0 [13963:13963:0315/202548.335561:6710750632:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000d9f0 [13963:13963:0315/202548.335602:6710750674:INFO:invalidation-client-core.cc(351)] Starting with no previous state [13963:13963:0315/202548.335651:6710750722:INFO:recurring-task.cc(55)] [Startup] Scheduling 238120 with a delay 0, Now = 210919424 [13963:13963:0315/202548.335693:6710750766:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da10 with delay 0 [13963:13963:0315/202548.335744:6710750817:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000da10 [13963:13963:0315/202548.335832:6710750918:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "2563424084230215558" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [13963:13963:0315/202548.335901:6710750975:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 238376 with a delay 500000, Now = 210919424 [13963:13963:0315/202548.335949:6710751021:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da30 with delay 500 [13963:13963:0315/202548.336015:6710751087:INFO:recurring-task.cc(55)] [Retry] Scheduling 238120 with a delay 60000000, Now = 210919424 [13963:13963:0315/202548.336062:6710751135:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000da50 with delay 60000 [13963:13963:0315/202548.336122:6710751196:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000da30 [13963:13963:0315/202548.336182:6710751254:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.336250:6710751323:INFO:invalidation-client-core.cc(488)] Return client token = "" [13963:13963:0315/202548.336424:6710751496: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: "2563424084230215558" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [13963:13963:0315/202548.336577:6710751649:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000daf0 with delay 0 [13963:13963:0315/202548.336622:6710751695:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000daf0 [13963:13963:0315/202548.336805:6710751880:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "2563424084230215558" 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" } } [13963:13963:0315/202548.336912:6710751984:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "2563424084230215558" [13963:13963:0315/202548.336984:6710752057:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [13963:13963:0315/202548.337034:6710752109:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 39848 with a delay 1200000000, Now = 211419424 [13963:13963:0315/202548.337080:6710752151:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000db10 with delay 1200000 [13963:13963:0315/202548.337128:6710752200:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [13963:13963:0315/202548.337326:6710752399:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13963:13963:0315/202548.337377:6710752450:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 68424 with a delay 0, Now = 211419424 [13963:13963:0315/202548.337423:6710752496:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000dd30 with delay 0 [13963:13963:0315/202548.337495:6710752569: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 [13963:13963:0315/202548.337551:6710752623:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000dd30 [13963:13963:0315/202548.337639:6710752712:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ddf0 with delay 0 [13963:13963:0315/202548.337699:6710752771:INFO:recurring-task.cc(55)] [Retry] Scheduling 68424 with a delay 10000000, Now = 211419424 [13963:13963:0315/202548.337751:6710752822:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000de30 with delay 10000 [13963:13963:0315/202548.337815:6710752887:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ddf0 [13963:13963:0315/202548.337874:6710752947:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [13963:13963:0315/202548.338307:6710753380:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000de30 [13963:13963:0315/202548.339743:6710754816:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000da50 [13963:13963:0315/202548.364995:6710780067:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x60200000db10 [13963:13963:0315/202548.365083:6710780151:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13963:13963:0315/202548.365139:6710780206:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [13963:13963:0315/202548.365178:6710780245:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [13963:13963:0315/202548.365361:6710780430: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 } [13963:13963:0315/202548.365417:6710780484:INFO:recurring-task.cc(55)] [Send-info] Scheduling 238376 with a delay 500000, Now = 1411419424 [13963:13963:0315/202548.365447:6710780514:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000de50 with delay 500 [13963:13963:0315/202548.365478:6710780545:INFO:recurring-task.cc(55)] [Retry] Scheduling 39848 with a delay 1200000000, Now = 1411419424 [13963:13963:0315/202548.365505:6710780570:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000de70 with delay 1200000 [13963:13963:0315/202548.365548:6710780615:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x60200000de50 [13963:13963:0315/202548.365582:6710780649:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.365643:6710780712:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [13963:13963:0315/202548.365669:6710780735:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [13963:13963:0315/202548.365889:6710780956:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 778801000 max_known_server_time_ms: 314159265 message_id: "2" } info_message: { client_version: { version: { major_version: 3 minor_version: 20140204 } platform: "unit-test" language: "C++" application_info: "InvClientTest" } performance_counter: { name: "SentMessageType.INITIALIZE" value: 1 } performance_counter: { name: "SentMessageType.TOTAL" value: 1 } performance_counter: { name: "ReceivedMessageType.TOKEN_CONTROL" value: 1 } performance_counter: { name: "ReceivedMessageType.TOTAL" value: 1 } performance_counter: { name: "ListenerEventType.REISSUE_REGISTRATIONS" value: 1 } performance_counter: { name: "ClientErrorType.PERSISTENT_READ_FAILURE" value: 1 } server_registration_summary_requested: false } } [ OK ] InvalidationClientImplTest.Heartbeats (33 ms) [28/28] InvalidationClientImplTest.Heartbeats (33 ms) SUCCESS: all tests passed. Tests took 0 seconds. 2019-03-17 22:59:03,973 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmpV3iUpW/43a82d23e0b31610'] 2019-03-17 22:59:03,974 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmpV3iUpW/43a82d23e0b31610/output.json'] 2019-03-17 22:59:03,974 - root: [INFO] merge_cmd: /b/swarming/w/ir/cache/vpython/6e0330/bin/python /b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --build-properties {"bot_id": "swarm594-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552888211363314, "id": "8918672406840449088", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ASan LSan Tests (1)/58435", "builder:Linux ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ASan LSan Builder", "parent_buildnumber:69536", "scheduler_invocation_id:9084102468832875584", "scheduler_job_id:chromium/Linux ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ASan LSan Tests (1)", "buildnumber": 58435, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "931311700c7c4b76a15c23eee8792dda125fb97e", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "got_revision_cp": "refs/heads/master@{#641522}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "got_webrtc_revision": "69008a87185992aa348ece3f893f6a84f8786ae8", "got_webrtc_revision_cp": "refs/heads/master@{#27145}", "mastername": "chromium.memory", "parent_buildername": "Linux ASan LSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "931311700c7c4b76a15c23eee8792dda125fb97e", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "parent_got_revision_cp": "refs/heads/master@{#641522}", "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": "69008a87185992aa348ece3f893f6a84f8786ae8", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27145}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "swarm_hashes": {"accessibility_unittests": "b93ce36bda8e63d0c3db86e3a8511ba873be70c3", "angle_unittests": "0af575e13122abb81d81d60250bb47e80545adac", "app_shell_unittests": "57a042252d33fb75475093e862db590904ca92ee", "aura_unittests": "2f4942a7227e10f8dd32cf75b768d0d8ce95c694", "base_unittests": "b7f824a4b2b21449edcad45705e193a59e6374d5", "blink_common_unittests": "71e2cee3cf16e2c865e2a0c7ee3d2b8b2eafaa79", "blink_fuzzer_unittests": "1520479d18bcf4a3cdadacb47885ab6898f4e4ff", "blink_heap_unittests": "4614721b4b122e97f648bcc158b13368aa84d18a", "blink_platform_unittests": "a5d37f9d592084c222ed29c4061bbb870ed5f696", "blink_unittests": "4b8a48790e4100cf28728831a58802d612c46975", "boringssl_crypto_tests": "e6886e6ca7b6e7e3be01afd2a59dc54577ec2692", "boringssl_ssl_tests": "fbf83af7ac2a5431bf30d777d49b56c55f2dc8fa", "browser_tests": "0041228e326cd756f4db8c53276fb89808703989", "cacheinvalidation_unittests": "2140fcf91e5897baf25cc0b3270375ea82fcb728", "capture_unittests": "0a5fe24da2021b333d19e905a20840c7a6975eeb", "cast_unittests": "b9c431df4e57d1f75a2ba7dfb49340bae27d12ed", "cc_unittests": "7afa1fc822a39c00ca574042dd3d445945c9594d", "chrome_app_unittests": "87195eccbb5719b0779b7375e815e53fa4a539ff", "chromedriver_unittests": "de5280689ec518c8783c6ecb4f6bec5b7952549b", "components_browsertests": "fbd614f9d47abfbc8c9537d36eb9b772fed284ce", "components_unittests": "1722a7cd5acff614d4d04e4d7b43e6b7c32e5c16", "compositor_unittests": "eada63e5e81fa7b3159865a92c45f8437ffe8bb9", "content_browsertests": "0dbf82340328ee3921157f9ce91e89d8044879fb", "content_unittests": "0236cc9195f1446deb679e75ccfe3f225e13e271", "cronet_tests": "0c3d059ff37f5f811676a3b3237018360c37bd08", "cronet_unittests": "a879e2695bc7c6706c0d88e443a2185315805c34", "crypto_unittests": "4c19cc69455f6e992bf49eb23c5f2e335d5fe63c", "dbus_unittests": "4aba2723e8a194be3e87193f7dde9c8b2a202b3d", "device_unittests": "2c6a22238da99d9f47efc46f1fb7f3c6f5d9847c", "display_unittests": "25ea0a46f20fcfae3a4b2d72ac49003ef9bc07c3", "events_unittests": "9fd456692a24299acdcf42eadb7d196ad5b512f5", "extensions_browsertests": "54e3b202c1d8e857c143a02d16e2b6556dd962c2", "extensions_unittests": "646bd2a67710cfa8a25e983223bc5f0866c95c6f", "filesystem_service_unittests": "2872f5a63ce20307eb6ab213ff89b4593b824466", "gcm_unit_tests": "71eb0428b8e07348b75336fd1bc790ae896b37ba", "gfx_unittests": "50e968dff9f430a2fd513bcd82b2766cfa0d0a0f", "gl_tests": "f986ac09446c64d213b1d5521b843d8481065297", "gl_unittests": "70b2052fee0da1da6c5aac4a0fe3fb46d192dcfc", "google_apis_unittests": "7dd42f76e0967186ac8d0d83b5615a75de030361", "gpu_unittests": "d407f194039e2dcb550749618deb0f0c609c5d67", "headless_browsertests": "5858412c39c6beb2893b084425b30dbde37a970c", "headless_unittests": "011e5958eb5070fd01d01afff4c9ca795767819c", "interactive_ui_tests": "23cdfdccc97f9035b454903a9596b829b94a9386", "ipc_tests": "7cb79d0d5c80aec55f0c2271552211dd1dcdd298", "jingle_unittests": "3e70873cf602ab532d1d67d93eb617ba6a3ff0a4", "latency_unittests": "d5f118c3a418346558365d9c508568df5a0ab111", "leveldb_service_unittests": "51b36762ae696d4633ba02bd97b823515d9fdda9", "libjingle_xmpp_unittests": "57a7f9d96bcd356c8943a6a9397d5abc1158496a", "media_blink_unittests": "7eb9745a4fdaa97fd9f8de771add01b7f7e56a70", "media_service_unittests": "33b0efaeb4bb1bf80d2b920f2968374522ead2c1", "media_unittests": "00d6b751d2ebef58492d6ad4a504f22d916b0d3d", "message_center_unittests": "253e7ed6fa4053b954455c2969e2ca42963ace6f", "midi_unittests": "a768d190fc425a6abfb2ac961d9d575643b69308", "mojo_core_unittests": "621f7f3d700d0f27049c15f6de21535e41e38c9c", "mojo_unittests": "c4b7802532809ec390a8a44ff1dd50ba6aa20920", "nacl_helper_nonsfi_unittests": "17462eb9f3e57ea3f538e034542d3e330fef8294", "nacl_loader_unittests": "6cc7c87856aaa47a095bf117f6406ef5b5cb5f0f", "native_theme_unittests": "630815d99794873fb6a94f68581009c010ea30a0", "net_unittests": "8b46341b55b90832a2bc6465205b4ccd59661251", "pdf_unittests": "86b7517e5cf1df00c077a4b12c21de31c0bebd8a", "ppapi_unittests": "8fc08723bf5c36732d0be627dd516d4ff0946854", "printing_unittests": "53899a805f2ce13c628d8e3109a00bf13b10c4ba", "remoting_unittests": "a1d1f078636f862918ecba862085e6e187d4190b", "sandbox_linux_unittests": "394822e9e6898ad28d5d05db7b39acff95389dd4", "service_manager_unittests": "14643576039d745ae53e7ebf56fd8beaf6a71cd0", "services_unittests": "efd7c9e243d7634fe08af07aa664f5ce3504d3dd", "shell_dialogs_unittests": "3596d68cf87afaa58078b069084e3e8d6cb4e904", "skia_unittests": "1201a78c4ab2349b059f5abeb488a995635b82ac", "snapshot_unittests": "e8c2d96e05befd34316cb2958367ca6d817d6cf7", "sql_unittests": "8a99a08e32e73cd2d359554b7ac6efa3bf372f18", "storage_unittests": "fe84d00a1821a5eff281de91df4478118a087430", "sync_integration_tests": "f61d6e99a591b452e0327f6b79a7d74ca4dd90bb", "traffic_annotation_auditor_unittests": "90c980e0dfd090d010df1e93eef20b67f51eda29", "ui_base_unittests": "6e2a605acca67a96cc8c53e1f2fc7f3fc39cb254", "ui_touch_selection_unittests": "e4d43769343933032cd703ad4acd7c3dd3470c4e", "unit_tests": "7d43e8898d90761f7c92ce6c11c1014d922b9070", "url_unittests": "a65e41ee14224dd132baa0b124dcaef033789555", "views_unittests": "cad6aac646b0dac1871e4ed27a161e99aed30b30", "viz_unittests": "6c7d58343a3ec826769e1f3186805dc232a695c9", "vr_common_unittests": "433418846d79e098393cc8103a0eabd8d3682f34", "vr_pixeltests": "50cff0389f600a4d5fe7c4539ef877d2e215041e", "wm_unittests": "c5c458768f71ebde213123b957033314874d9115", "wtf_unittests": "15e99f0d3c33cba3f23abc84135781df4172aa4a"}} --summary-json /b/swarming/w/ir/tmp/t/tmp7c2Oyr.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpV3iUpW -o /b/swarming/w/ir/tmp/t/tmpByEeX3.json /b/swarming/w/ir/tmp/t/tmpV3iUpW/43a82d23e0b31610/output.json Running ['/b/swarming/w/ir/cache/vpython/6e0330/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "swarm594-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552888211363314, "id": "8918672406840449088", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ASan LSan Tests (1)/58435", "builder:Linux ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ASan LSan Builder", "parent_buildnumber:69536", "scheduler_invocation_id:9084102468832875584", "scheduler_job_id:chromium/Linux ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ASan LSan Tests (1)", "buildnumber": 58435, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "931311700c7c4b76a15c23eee8792dda125fb97e", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "got_revision_cp": "refs/heads/master@{#641522}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "got_webrtc_revision": "69008a87185992aa348ece3f893f6a84f8786ae8", "got_webrtc_revision_cp": "refs/heads/master@{#27145}", "mastername": "chromium.memory", "parent_buildername": "Linux ASan LSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "931311700c7c4b76a15c23eee8792dda125fb97e", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "parent_got_revision_cp": "refs/heads/master@{#641522}", "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": "69008a87185992aa348ece3f893f6a84f8786ae8", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27145}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "swarm_hashes": {"accessibility_unittests": "b93ce36bda8e63d0c3db86e3a8511ba873be70c3", "angle_unittests": "0af575e13122abb81d81d60250bb47e80545adac", "app_shell_unittests": "57a042252d33fb75475093e862db590904ca92ee", "aura_unittests": "2f4942a7227e10f8dd32cf75b768d0d8ce95c694", "base_unittests": "b7f824a4b2b21449edcad45705e193a59e6374d5", "blink_common_unittests": "71e2cee3cf16e2c865e2a0c7ee3d2b8b2eafaa79", "blink_fuzzer_unittests": "1520479d18bcf4a3cdadacb47885ab6898f4e4ff", "blink_heap_unittests": "4614721b4b122e97f648bcc158b13368aa84d18a", "blink_platform_unittests": "a5d37f9d592084c222ed29c4061bbb870ed5f696", "blink_unittests": "4b8a48790e4100cf28728831a58802d612c46975", "boringssl_crypto_tests": "e6886e6ca7b6e7e3be01afd2a59dc54577ec2692", "boringssl_ssl_tests": "fbf83af7ac2a5431bf30d777d49b56c55f2dc8fa", "browser_tests": "0041228e326cd756f4db8c53276fb89808703989", "cacheinvalidation_unittests": "2140fcf91e5897baf25cc0b3270375ea82fcb728", "capture_unittests": "0a5fe24da2021b333d19e905a20840c7a6975eeb", "cast_unittests": "b9c431df4e57d1f75a2ba7dfb49340bae27d12ed", "cc_unittests": "7afa1fc822a39c00ca574042dd3d445945c9594d", "chrome_app_unittests": "87195eccbb5719b0779b7375e815e53fa4a539ff", "chromedriver_unittests": "de5280689ec518c8783c6ecb4f6bec5b7952549b", "components_browsertests": "fbd614f9d47abfbc8c9537d36eb9b772fed284ce", "components_unittests": "1722a7cd5acff614d4d04e4d7b43e6b7c32e5c16", "compositor_unittests": "eada63e5e81fa7b3159865a92c45f8437ffe8bb9", "content_browsertests": "0dbf82340328ee3921157f9ce91e89d8044879fb", "content_unittests": "0236cc9195f1446deb679e75ccfe3f225e13e271", "cronet_tests": "0c3d059ff37f5f811676a3b3237018360c37bd08", "cronet_unittests": "a879e2695bc7c6706c0d88e443a2185315805c34", "crypto_unittests": "4c19cc69455f6e992bf49eb23c5f2e335d5fe63c", "dbus_unittests": "4aba2723e8a194be3e87193f7dde9c8b2a202b3d", "device_unittests": "2c6a22238da99d9f47efc46f1fb7f3c6f5d9847c", "display_unittests": "25ea0a46f20fcfae3a4b2d72ac49003ef9bc07c3", "events_unittests": "9fd456692a24299acdcf42eadb7d196ad5b512f5", "extensions_browsertests": "54e3b202c1d8e857c143a02d16e2b6556dd962c2", "extensions_unittests": "646bd2a67710cfa8a25e983223bc5f0866c95c6f", "filesystem_service_unittests": "2872f5a63ce20307eb6ab213ff89b4593b824466", "gcm_unit_tests": "71eb0428b8e07348b75336fd1bc790ae896b37ba", "gfx_unittests": "50e968dff9f430a2fd513bcd82b2766cfa0d0a0f", "gl_tests": "f986ac09446c64d213b1d5521b843d8481065297", "gl_unittests": "70b2052fee0da1da6c5aac4a0fe3fb46d192dcfc", "google_apis_unittests": "7dd42f76e0967186ac8d0d83b5615a75de030361", "gpu_unittests": "d407f194039e2dcb550749618deb0f0c609c5d67", "headless_browsertests": "5858412c39c6beb2893b084425b30dbde37a970c", "headless_unittests": "011e5958eb5070fd01d01afff4c9ca795767819c", "interactive_ui_tests": "23cdfdccc97f9035b454903a9596b829b94a9386", "ipc_tests": "7cb79d0d5c80aec55f0c2271552211dd1dcdd298", "jingle_unittests": "3e70873cf602ab532d1d67d93eb617ba6a3ff0a4", "latency_unittests": "d5f118c3a418346558365d9c508568df5a0ab111", "leveldb_service_unittests": "51b36762ae696d4633ba02bd97b823515d9fdda9", "libjingle_xmpp_unittests": "57a7f9d96bcd356c8943a6a9397d5abc1158496a", "media_blink_unittests": "7eb9745a4fdaa97fd9f8de771add01b7f7e56a70", "media_service_unittests": "33b0efaeb4bb1bf80d2b920f2968374522ead2c1", "media_unittests": "00d6b751d2ebef58492d6ad4a504f22d916b0d3d", "message_center_unittests": "253e7ed6fa4053b954455c2969e2ca42963ace6f", "midi_unittests": "a768d190fc425a6abfb2ac961d9d575643b69308", "mojo_core_unittests": "621f7f3d700d0f27049c15f6de21535e41e38c9c", "mojo_unittests": "c4b7802532809ec390a8a44ff1dd50ba6aa20920", "nacl_helper_nonsfi_unittests": "17462eb9f3e57ea3f538e034542d3e330fef8294", "nacl_loader_unittests": "6cc7c87856aaa47a095bf117f6406ef5b5cb5f0f", "native_theme_unittests": "630815d99794873fb6a94f68581009c010ea30a0", "net_unittests": "8b46341b55b90832a2bc6465205b4ccd59661251", "pdf_unittests": "86b7517e5cf1df00c077a4b12c21de31c0bebd8a", "ppapi_unittests": "8fc08723bf5c36732d0be627dd516d4ff0946854", "printing_unittests": "53899a805f2ce13c628d8e3109a00bf13b10c4ba", "remoting_unittests": "a1d1f078636f862918ecba862085e6e187d4190b", "sandbox_linux_unittests": "394822e9e6898ad28d5d05db7b39acff95389dd4", "service_manager_unittests": "14643576039d745ae53e7ebf56fd8beaf6a71cd0", "services_unittests": "efd7c9e243d7634fe08af07aa664f5ce3504d3dd", "shell_dialogs_unittests": "3596d68cf87afaa58078b069084e3e8d6cb4e904", "skia_unittests": "1201a78c4ab2349b059f5abeb488a995635b82ac", "snapshot_unittests": "e8c2d96e05befd34316cb2958367ca6d817d6cf7", "sql_unittests": "8a99a08e32e73cd2d359554b7ac6efa3bf372f18", "storage_unittests": "fe84d00a1821a5eff281de91df4478118a087430", "sync_integration_tests": "f61d6e99a591b452e0327f6b79a7d74ca4dd90bb", "traffic_annotation_auditor_unittests": "90c980e0dfd090d010df1e93eef20b67f51eda29", "ui_base_unittests": "6e2a605acca67a96cc8c53e1f2fc7f3fc39cb254", "ui_touch_selection_unittests": "e4d43769343933032cd703ad4acd7c3dd3470c4e", "unit_tests": "7d43e8898d90761f7c92ce6c11c1014d922b9070", "url_unittests": "a65e41ee14224dd132baa0b124dcaef033789555", "views_unittests": "cad6aac646b0dac1871e4ed27a161e99aed30b30", "viz_unittests": "6c7d58343a3ec826769e1f3186805dc232a695c9", "vr_common_unittests": "433418846d79e098393cc8103a0eabd8d3682f34", "vr_pixeltests": "50cff0389f600a4d5fe7c4539ef877d2e215041e", "wm_unittests": "c5c458768f71ebde213123b957033314874d9115", "wtf_unittests": "15e99f0d3c33cba3f23abc84135781df4172aa4a"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp7c2Oyr.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpV3iUpW', '-o', '/b/swarming/w/ir/tmp/t/tmpByEeX3.json', '/b/swarming/w/ir/tmp/t/tmpV3iUpW/43a82d23e0b31610/output.json'] in None (env: None) Command ['/b/swarming/w/ir/cache/vpython/6e0330/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "swarm594-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1552888211363314, "id": "8918672406840449088", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux ASan LSan Tests (1)/58435", "builder:Linux ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "gitiles_ref:refs/heads/master", "parent_buildername:Linux ASan LSan Builder", "parent_buildnumber:69536", "scheduler_invocation_id:9084102468832875584", "scheduler_job_id:chromium/Linux ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux ASan LSan Tests (1)", "buildnumber": 58435, "got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "got_dawn_revision": "931311700c7c4b76a15c23eee8792dda125fb97e", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "got_revision_cp": "refs/heads/master@{#641522}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "f413181b62ee4ad78b9ef3d58c4f395794e16bf1", "got_v8_revision_cp": "refs/heads/7.5.59@{#1}", "got_webrtc_revision": "69008a87185992aa348ece3f893f6a84f8786ae8", "got_webrtc_revision_cp": "refs/heads/master@{#27145}", "mastername": "chromium.memory", "parent_buildername": "Linux ASan LSan Builder", "parent_got_angle_revision": "38e282570676f3e434482f8a02ea539b286fd1fa", "parent_got_dawn_revision": "931311700c7c4b76a15c23eee8792dda125fb97e", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "parent_got_revision_cp": "refs/heads/master@{#641522}", "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": "69008a87185992aa348ece3f893f6a84f8786ae8", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27145}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "bcb7520bbd56c33a3ed6b5f7aded0f262fe30217", "swarm_hashes": {"accessibility_unittests": "b93ce36bda8e63d0c3db86e3a8511ba873be70c3", "angle_unittests": "0af575e13122abb81d81d60250bb47e80545adac", "app_shell_unittests": "57a042252d33fb75475093e862db590904ca92ee", "aura_unittests": "2f4942a7227e10f8dd32cf75b768d0d8ce95c694", "base_unittests": "b7f824a4b2b21449edcad45705e193a59e6374d5", "blink_common_unittests": "71e2cee3cf16e2c865e2a0c7ee3d2b8b2eafaa79", "blink_fuzzer_unittests": "1520479d18bcf4a3cdadacb47885ab6898f4e4ff", "blink_heap_unittests": "4614721b4b122e97f648bcc158b13368aa84d18a", "blink_platform_unittests": "a5d37f9d592084c222ed29c4061bbb870ed5f696", "blink_unittests": "4b8a48790e4100cf28728831a58802d612c46975", "boringssl_crypto_tests": "e6886e6ca7b6e7e3be01afd2a59dc54577ec2692", "boringssl_ssl_tests": "fbf83af7ac2a5431bf30d777d49b56c55f2dc8fa", "browser_tests": "0041228e326cd756f4db8c53276fb89808703989", "cacheinvalidation_unittests": "2140fcf91e5897baf25cc0b3270375ea82fcb728", "capture_unittests": "0a5fe24da2021b333d19e905a20840c7a6975eeb", "cast_unittests": "b9c431df4e57d1f75a2ba7dfb49340bae27d12ed", "cc_unittests": "7afa1fc822a39c00ca574042dd3d445945c9594d", "chrome_app_unittests": "87195eccbb5719b0779b7375e815e53fa4a539ff", "chromedriver_unittests": "de5280689ec518c8783c6ecb4f6bec5b7952549b", "components_browsertests": "fbd614f9d47abfbc8c9537d36eb9b772fed284ce", "components_unittests": "1722a7cd5acff614d4d04e4d7b43e6b7c32e5c16", "compositor_unittests": "eada63e5e81fa7b3159865a92c45f8437ffe8bb9", "content_browsertests": "0dbf82340328ee3921157f9ce91e89d8044879fb", "content_unittests": "0236cc9195f1446deb679e75ccfe3f225e13e271", "cronet_tests": "0c3d059ff37f5f811676a3b3237018360c37bd08", "cronet_unittests": "a879e2695bc7c6706c0d88e443a2185315805c34", "crypto_unittests": "4c19cc69455f6e992bf49eb23c5f2e335d5fe63c", "dbus_unittests": "4aba2723e8a194be3e87193f7dde9c8b2a202b3d", "device_unittests": "2c6a22238da99d9f47efc46f1fb7f3c6f5d9847c", "display_unittests": "25ea0a46f20fcfae3a4b2d72ac49003ef9bc07c3", "events_unittests": "9fd456692a24299acdcf42eadb7d196ad5b512f5", "extensions_browsertests": "54e3b202c1d8e857c143a02d16e2b6556dd962c2", "extensions_unittests": "646bd2a67710cfa8a25e983223bc5f0866c95c6f", "filesystem_service_unittests": "2872f5a63ce20307eb6ab213ff89b4593b824466", "gcm_unit_tests": "71eb0428b8e07348b75336fd1bc790ae896b37ba", "gfx_unittests": "50e968dff9f430a2fd513bcd82b2766cfa0d0a0f", "gl_tests": "f986ac09446c64d213b1d5521b843d8481065297", "gl_unittests": "70b2052fee0da1da6c5aac4a0fe3fb46d192dcfc", "google_apis_unittests": "7dd42f76e0967186ac8d0d83b5615a75de030361", "gpu_unittests": "d407f194039e2dcb550749618deb0f0c609c5d67", "headless_browsertests": "5858412c39c6beb2893b084425b30dbde37a970c", "headless_unittests": "011e5958eb5070fd01d01afff4c9ca795767819c", "interactive_ui_tests": "23cdfdccc97f9035b454903a9596b829b94a9386", "ipc_tests": "7cb79d0d5c80aec55f0c2271552211dd1dcdd298", "jingle_unittests": "3e70873cf602ab532d1d67d93eb617ba6a3ff0a4", "latency_unittests": "d5f118c3a418346558365d9c508568df5a0ab111", "leveldb_service_unittests": "51b36762ae696d4633ba02bd97b823515d9fdda9", "libjingle_xmpp_unittests": "57a7f9d96bcd356c8943a6a9397d5abc1158496a", "media_blink_unittests": "7eb9745a4fdaa97fd9f8de771add01b7f7e56a70", "media_service_unittests": "33b0efaeb4bb1bf80d2b920f2968374522ead2c1", "media_unittests": "00d6b751d2ebef58492d6ad4a504f22d916b0d3d", "message_center_unittests": "253e7ed6fa4053b954455c2969e2ca42963ace6f", "midi_unittests": "a768d190fc425a6abfb2ac961d9d575643b69308", "mojo_core_unittests": "621f7f3d700d0f27049c15f6de21535e41e38c9c", "mojo_unittests": "c4b7802532809ec390a8a44ff1dd50ba6aa20920", "nacl_helper_nonsfi_unittests": "17462eb9f3e57ea3f538e034542d3e330fef8294", "nacl_loader_unittests": "6cc7c87856aaa47a095bf117f6406ef5b5cb5f0f", "native_theme_unittests": "630815d99794873fb6a94f68581009c010ea30a0", "net_unittests": "8b46341b55b90832a2bc6465205b4ccd59661251", "pdf_unittests": "86b7517e5cf1df00c077a4b12c21de31c0bebd8a", "ppapi_unittests": "8fc08723bf5c36732d0be627dd516d4ff0946854", "printing_unittests": "53899a805f2ce13c628d8e3109a00bf13b10c4ba", "remoting_unittests": "a1d1f078636f862918ecba862085e6e187d4190b", "sandbox_linux_unittests": "394822e9e6898ad28d5d05db7b39acff95389dd4", "service_manager_unittests": "14643576039d745ae53e7ebf56fd8beaf6a71cd0", "services_unittests": "efd7c9e243d7634fe08af07aa664f5ce3504d3dd", "shell_dialogs_unittests": "3596d68cf87afaa58078b069084e3e8d6cb4e904", "skia_unittests": "1201a78c4ab2349b059f5abeb488a995635b82ac", "snapshot_unittests": "e8c2d96e05befd34316cb2958367ca6d817d6cf7", "sql_unittests": "8a99a08e32e73cd2d359554b7ac6efa3bf372f18", "storage_unittests": "fe84d00a1821a5eff281de91df4478118a087430", "sync_integration_tests": "f61d6e99a591b452e0327f6b79a7d74ca4dd90bb", "traffic_annotation_auditor_unittests": "90c980e0dfd090d010df1e93eef20b67f51eda29", "ui_base_unittests": "6e2a605acca67a96cc8c53e1f2fc7f3fc39cb254", "ui_touch_selection_unittests": "e4d43769343933032cd703ad4acd7c3dd3470c4e", "unit_tests": "7d43e8898d90761f7c92ce6c11c1014d922b9070", "url_unittests": "a65e41ee14224dd132baa0b124dcaef033789555", "views_unittests": "cad6aac646b0dac1871e4ed27a161e99aed30b30", "viz_unittests": "6c7d58343a3ec826769e1f3186805dc232a695c9", "vr_common_unittests": "433418846d79e098393cc8103a0eabd8d3682f34", "vr_pixeltests": "50cff0389f600a4d5fe7c4539ef877d2e215041e", "wm_unittests": "c5c458768f71ebde213123b957033314874d9115", "wtf_unittests": "15e99f0d3c33cba3f23abc84135781df4172aa4a"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp7c2Oyr.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpV3iUpW', '-o', '/b/swarming/w/ir/tmp/t/tmpByEeX3.json', '/b/swarming/w/ir/tmp/t/tmpV3iUpW/43a82d23e0b31610/output.json'] returned exit code 0