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/tmpcjeF9o.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpANdRtW --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/tmp9bA3F_merge_script_log --merge-additional-args '[]' --build-properties '{"bot_id": "swarm323-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "user:luci-scheduler@appspot.gserviceaccount.com", "created_ts": 1552583359521792, "id": "8918992067164676304", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux TSan Tests/35497", "builder:Linux TSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "gitiles_ref:refs/heads/master", "parent_buildername:Linux TSan Builder", "parent_buildnumber:42725", "scheduler_invocation_id:9084422129189990416", "scheduler_job_id:chromium/Linux TSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux TSan Tests", "buildnumber": 35497, "got_angle_revision": "094c40dce6015add9e9524364a4e9b0523b7c31e", "got_dawn_revision": "ea2c7f20f2f96e15570f7e9416fb6c826f809747", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "got_revision_cp": "refs/heads/master@{#640796}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "a4404f08610f8dde2b745329ac5813c4a6a84c70", "got_v8_revision_cp": "refs/heads/7.5.38@{#1}", "got_webrtc_revision": "d841ea6b586a81065f78d3eae7ab82c505cda1d8", "got_webrtc_revision_cp": "refs/heads/master@{#27121}", "mastername": "chromium.memory", "parent_buildername": "Linux TSan Builder", "parent_got_angle_revision": "094c40dce6015add9e9524364a4e9b0523b7c31e", "parent_got_dawn_revision": "ea2c7f20f2f96e15570f7e9416fb6c826f809747", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "parent_got_revision_cp": "refs/heads/master@{#640796}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "a4404f08610f8dde2b745329ac5813c4a6a84c70", "parent_got_v8_revision_cp": "refs/heads/7.5.38@{#1}", "parent_got_webrtc_revision": "d841ea6b586a81065f78d3eae7ab82c505cda1d8", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27121}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "swarm_hashes": {"accessibility_unittests": "bd5e6db4b676fd014f55de6b34acb38814e4023e", "angle_unittests": "763013b4e1e6cdc25c633b4baf9c75bf9813d31d", "app_shell_unittests": "73c709a5168eb6dcc5eaa96a04867dcd015ebe02", "aura_unittests": "9966646d4921361777ad77e183761b3f8a07e14f", "base_unittests": "6b61b4ca9c6dfdab5c394b15f5c1fa4f9dcfacf7", "blink_common_unittests": "770987225d223ba70c446a2e3a1e10ed1257fc8e", "blink_fuzzer_unittests": "848509de7a997a9d9bd09bf01340e2259106ddd6", "blink_heap_unittests": "950ea8d2aa3f9688635bf57ea6922703a2a39a91", "blink_platform_unittests": "7548ee8138505558f830afca909aee02939a159f", "blink_unittests": "b52ea8255ceb02e01e6e630ab6e348191f0104cd", "boringssl_crypto_tests": "31383dd12bb3660af192869f1d660b5162147258", "boringssl_ssl_tests": "86cf06d1fc726982075785f5a3df40b415e14a4f", "browser_tests": "daf81ca849328c89b3b0679f4c07406b769ec737", "cacheinvalidation_unittests": "ef2168a186aaef68c64438486a235648f9bda843", "capture_unittests": "7751f7713228751b0b0b76ec905ce369e207a953", "cast_unittests": "e9b89adcd935e40a559b010471f939f0e86fea24", "cc_unittests": "668162daa3b5140e91059e2a076e15021edc67c7", "chrome_app_unittests": "fb5e0852ee27894a9107973d9aa3e80333939580", "chromedriver_unittests": "d0944dc48261781dbd121016fb7d726379a7ac6c", "components_browsertests": "bf9a0a2f78d92969c1b9bfc8c93db39f0b05bbda", "components_unittests": "38ad8d50e0ba8d00a151157e2a5d48f4417dd2be", "compositor_unittests": "ccb73ae8ed014bc9c42a76b8c03c3f04ae97dab1", "content_browsertests": "e7dc36a62b86e573733d3bf046c1adef9bfb91df", "content_unittests": "5c5b73aa5b00bdefe6462852dbef1fec3680648a", "cronet_tests": "f13f11ae3f6798ced9f62384bc49293707d35a08", "cronet_unittests": "266b1a9e4b21aebbc20315925f07bb4dacec080c", "crypto_unittests": "a3fbc979f2894c146fe361e9d0cb4be21441d1c2", "dbus_unittests": "117b2a60cb55d8f25f0ed393e361e595fd2857ba", "device_unittests": "a92e33d257709c54dee6678cd1f08a12b9438843", "display_unittests": "47d228897c6ab66e59f007797df4ffbda9af4abf", "events_unittests": "fc10681c10d993dce7219c5f2dd9a8760dd18610", "extensions_browsertests": "e176916ac6aa6c574c781a3b07bc9b9dbac460c0", "extensions_unittests": "797e258b6a8cffb3af29f5c18d822282c1586cab", "filesystem_service_unittests": "ba4e555ccdea82e74fa902ec804dae749e480f71", "gcm_unit_tests": "b65d823adeeca128a04bddd2bd2c49d782bb33c2", "gfx_unittests": "432fa939836128a9084aea053edaec59487a2bbe", "gin_unittests": "f0207bc128b4d4c0e0808f5ce300a580c682fd26", "gl_tests": "a8b7bc256d2cf7df81af028cc61ba60c87669e1c", "gl_unittests": "f3c6fda5e9a97f7d8ac0fcfcd9d2ef9fd441afa4", "google_apis_unittests": "7ba3fea8df71315f56a56b177cdc01158b09f04c", "gpu_unittests": "c7cb99cb3abb6b3eda007580ec184e564486d3fe", "headless_browsertests": "12e45c752dd9f778135a4bdfb57dc9f80b1a916f", "headless_unittests": "2818679ba67e08abe7e144180f7d678d28d9c7c1", "interactive_ui_tests": "5d12c3829e03421a53a90d010fa3b65be9565bf1", "ipc_tests": "efebeb50369a9c366d122983222eb032bd297d41", "jingle_unittests": "61e0cde960bd3d589778fe712636cefea4410b62", "latency_unittests": "740b1607db423ae552b6e3b51fb3bcfdec5eff48", "leveldb_service_unittests": "b012937976b230e898b7f97581e6dd8171849450", "libjingle_xmpp_unittests": "9e0cecaa9cb3c2ebbbfa7a40a334642b253bdee5", "media_blink_unittests": "6c800250e2649db391d93011d97dfb15aef4fcd2", "media_service_unittests": "5d61b49da07ca4d90d1c52de78735b809d685776", "media_unittests": "39f650d98f882d1e559214be6c3271fe97903668", "message_center_unittests": "58a1d2bd3cc0cf2831ac42789caeb6b6cd8ed9b9", "midi_unittests": "bb3c8312a59acaf25261e559978a6b14119e7cad", "mojo_core_unittests": "51bb216786158f43a5372bf71f220b45b78b00d2", "mojo_unittests": "332a327db1fbb5b10ffd36ab08d58053c954721b", "native_theme_unittests": "e88ff2f86c605ccd643af402a59df8027fbeefc5", "net_unittests": "f9219e6dcb1075d48015dcac1fd32dc70fdf967f", "pdf_unittests": "97d1cd2192aca19fabeb8118501996106b29c8a7", "ppapi_unittests": "1e409fd253b204a8a5305e266e68f67e0545f889", "printing_unittests": "361867963a06f2b6c7ac58e9f96f5ecead87ed87", "remoting_unittests": "d10b3257802f2235612f74cb6324ececa4f3bbc5", "sandbox_linux_unittests": "ad25386e7203628df7eac034c6e02e5514402582", "service_manager_unittests": "a67bf71132c7ac48e9f06865228980b64ae87f75", "services_unittests": "4fb66585b8b509415c56d1d493e913dc26865ba0", "shell_dialogs_unittests": "5ce654ddfe0031d9bc1627e108450ed17735e805", "skia_unittests": "c61a0726e2cafd000c577ce594cccc003311d3b4", "snapshot_unittests": "67dc7662cfe22d0163b9b12f6032bfeea437ac9a", "sql_unittests": "ab0b7c9a9458da975427b599665a2e36f077ead7", "storage_unittests": "b979bf5e0902aa2e47d8d6380c146038af2ca42d", "sync_integration_tests": "2dd07ab05e0a0082a8e224f7e50018180b8cb07a", "traffic_annotation_auditor_unittests": "418dcebad9a7a94cab8eba04dfff8dd03ad3407d", "ui_base_unittests": "689a5de29342598ccba2f34620d87c457d5cabe6", "ui_touch_selection_unittests": "aebef3735b434e20bf6a2f8f081e3df22cd56ee7", "unit_tests": "5aaca57f171465ebd6c9ef9c574ad248434ff23e", "url_unittests": "025e3dfdb9f142c6161fc0f9541b66752233e28c", "views_unittests": "4d9ba61910328eb5759c6af795888eda1eaac7fe", "viz_unittests": "104704e9e5b1dab1fba809b9e79c87255583219b", "vr_common_unittests": "b8a8c31335ce510a574e039eac392c299d0b70fd", "vr_pixeltests": "8209a6668387366fa6a1a4077a1eff0b1cb3d9d2", "wm_unittests": "e41e6ae46787272c70f332826821981414d6880b", "wtf_unittests": "4290e041f8ca577eb42f95a6e47dbcaabcbc23a1"}}' --summary-json-file /b/swarming/w/ir/tmp/t/tmp5r6Zoc.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/tmphjKkuk.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/tmpcjeF9o.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpANdRtW', '--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/tmp9bA3F_merge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"bot_id": "swarm323-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "user:luci-scheduler@appspot.gserviceaccount.com", "created_ts": 1552583359521792, "id": "8918992067164676304", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux TSan Tests/35497", "builder:Linux TSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "gitiles_ref:refs/heads/master", "parent_buildername:Linux TSan Builder", "parent_buildnumber:42725", "scheduler_invocation_id:9084422129189990416", "scheduler_job_id:chromium/Linux TSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux TSan Tests", "buildnumber": 35497, "got_angle_revision": "094c40dce6015add9e9524364a4e9b0523b7c31e", "got_dawn_revision": "ea2c7f20f2f96e15570f7e9416fb6c826f809747", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "got_revision_cp": "refs/heads/master@{#640796}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "a4404f08610f8dde2b745329ac5813c4a6a84c70", "got_v8_revision_cp": "refs/heads/7.5.38@{#1}", "got_webrtc_revision": "d841ea6b586a81065f78d3eae7ab82c505cda1d8", "got_webrtc_revision_cp": "refs/heads/master@{#27121}", "mastername": "chromium.memory", "parent_buildername": "Linux TSan Builder", "parent_got_angle_revision": "094c40dce6015add9e9524364a4e9b0523b7c31e", "parent_got_dawn_revision": "ea2c7f20f2f96e15570f7e9416fb6c826f809747", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "parent_got_revision_cp": "refs/heads/master@{#640796}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "a4404f08610f8dde2b745329ac5813c4a6a84c70", "parent_got_v8_revision_cp": "refs/heads/7.5.38@{#1}", "parent_got_webrtc_revision": "d841ea6b586a81065f78d3eae7ab82c505cda1d8", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27121}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "swarm_hashes": {"accessibility_unittests": "bd5e6db4b676fd014f55de6b34acb38814e4023e", "angle_unittests": "763013b4e1e6cdc25c633b4baf9c75bf9813d31d", "app_shell_unittests": "73c709a5168eb6dcc5eaa96a04867dcd015ebe02", "aura_unittests": "9966646d4921361777ad77e183761b3f8a07e14f", "base_unittests": "6b61b4ca9c6dfdab5c394b15f5c1fa4f9dcfacf7", "blink_common_unittests": "770987225d223ba70c446a2e3a1e10ed1257fc8e", "blink_fuzzer_unittests": "848509de7a997a9d9bd09bf01340e2259106ddd6", "blink_heap_unittests": "950ea8d2aa3f9688635bf57ea6922703a2a39a91", "blink_platform_unittests": "7548ee8138505558f830afca909aee02939a159f", "blink_unittests": "b52ea8255ceb02e01e6e630ab6e348191f0104cd", "boringssl_crypto_tests": "31383dd12bb3660af192869f1d660b5162147258", "boringssl_ssl_tests": "86cf06d1fc726982075785f5a3df40b415e14a4f", "browser_tests": "daf81ca849328c89b3b0679f4c07406b769ec737", "cacheinvalidation_unittests": "ef2168a186aaef68c64438486a235648f9bda843", "capture_unittests": "7751f7713228751b0b0b76ec905ce369e207a953", "cast_unittests": "e9b89adcd935e40a559b010471f939f0e86fea24", "cc_unittests": "668162daa3b5140e91059e2a076e15021edc67c7", "chrome_app_unittests": "fb5e0852ee27894a9107973d9aa3e80333939580", "chromedriver_unittests": "d0944dc48261781dbd121016fb7d726379a7ac6c", "components_browsertests": "bf9a0a2f78d92969c1b9bfc8c93db39f0b05bbda", "components_unittests": "38ad8d50e0ba8d00a151157e2a5d48f4417dd2be", "compositor_unittests": "ccb73ae8ed014bc9c42a76b8c03c3f04ae97dab1", "content_browsertests": "e7dc36a62b86e573733d3bf046c1adef9bfb91df", "content_unittests": "5c5b73aa5b00bdefe6462852dbef1fec3680648a", "cronet_tests": "f13f11ae3f6798ced9f62384bc49293707d35a08", "cronet_unittests": "266b1a9e4b21aebbc20315925f07bb4dacec080c", "crypto_unittests": "a3fbc979f2894c146fe361e9d0cb4be21441d1c2", "dbus_unittests": "117b2a60cb55d8f25f0ed393e361e595fd2857ba", "device_unittests": "a92e33d257709c54dee6678cd1f08a12b9438843", "display_unittests": "47d228897c6ab66e59f007797df4ffbda9af4abf", "events_unittests": "fc10681c10d993dce7219c5f2dd9a8760dd18610", "extensions_browsertests": "e176916ac6aa6c574c781a3b07bc9b9dbac460c0", "extensions_unittests": "797e258b6a8cffb3af29f5c18d822282c1586cab", "filesystem_service_unittests": "ba4e555ccdea82e74fa902ec804dae749e480f71", "gcm_unit_tests": "b65d823adeeca128a04bddd2bd2c49d782bb33c2", "gfx_unittests": "432fa939836128a9084aea053edaec59487a2bbe", "gin_unittests": "f0207bc128b4d4c0e0808f5ce300a580c682fd26", "gl_tests": "a8b7bc256d2cf7df81af028cc61ba60c87669e1c", "gl_unittests": "f3c6fda5e9a97f7d8ac0fcfcd9d2ef9fd441afa4", "google_apis_unittests": "7ba3fea8df71315f56a56b177cdc01158b09f04c", "gpu_unittests": "c7cb99cb3abb6b3eda007580ec184e564486d3fe", "headless_browsertests": "12e45c752dd9f778135a4bdfb57dc9f80b1a916f", "headless_unittests": "2818679ba67e08abe7e144180f7d678d28d9c7c1", "interactive_ui_tests": "5d12c3829e03421a53a90d010fa3b65be9565bf1", "ipc_tests": "efebeb50369a9c366d122983222eb032bd297d41", "jingle_unittests": "61e0cde960bd3d589778fe712636cefea4410b62", "latency_unittests": "740b1607db423ae552b6e3b51fb3bcfdec5eff48", "leveldb_service_unittests": "b012937976b230e898b7f97581e6dd8171849450", "libjingle_xmpp_unittests": "9e0cecaa9cb3c2ebbbfa7a40a334642b253bdee5", "media_blink_unittests": "6c800250e2649db391d93011d97dfb15aef4fcd2", "media_service_unittests": "5d61b49da07ca4d90d1c52de78735b809d685776", "media_unittests": "39f650d98f882d1e559214be6c3271fe97903668", "message_center_unittests": "58a1d2bd3cc0cf2831ac42789caeb6b6cd8ed9b9", "midi_unittests": "bb3c8312a59acaf25261e559978a6b14119e7cad", "mojo_core_unittests": "51bb216786158f43a5372bf71f220b45b78b00d2", "mojo_unittests": "332a327db1fbb5b10ffd36ab08d58053c954721b", "native_theme_unittests": "e88ff2f86c605ccd643af402a59df8027fbeefc5", "net_unittests": "f9219e6dcb1075d48015dcac1fd32dc70fdf967f", "pdf_unittests": "97d1cd2192aca19fabeb8118501996106b29c8a7", "ppapi_unittests": "1e409fd253b204a8a5305e266e68f67e0545f889", "printing_unittests": "361867963a06f2b6c7ac58e9f96f5ecead87ed87", "remoting_unittests": "d10b3257802f2235612f74cb6324ececa4f3bbc5", "sandbox_linux_unittests": "ad25386e7203628df7eac034c6e02e5514402582", "service_manager_unittests": "a67bf71132c7ac48e9f06865228980b64ae87f75", "services_unittests": "4fb66585b8b509415c56d1d493e913dc26865ba0", "shell_dialogs_unittests": "5ce654ddfe0031d9bc1627e108450ed17735e805", "skia_unittests": "c61a0726e2cafd000c577ce594cccc003311d3b4", "snapshot_unittests": "67dc7662cfe22d0163b9b12f6032bfeea437ac9a", "sql_unittests": "ab0b7c9a9458da975427b599665a2e36f077ead7", "storage_unittests": "b979bf5e0902aa2e47d8d6380c146038af2ca42d", "sync_integration_tests": "2dd07ab05e0a0082a8e224f7e50018180b8cb07a", "traffic_annotation_auditor_unittests": "418dcebad9a7a94cab8eba04dfff8dd03ad3407d", "ui_base_unittests": "689a5de29342598ccba2f34620d87c457d5cabe6", "ui_touch_selection_unittests": "aebef3735b434e20bf6a2f8f081e3df22cd56ee7", "unit_tests": "5aaca57f171465ebd6c9ef9c574ad248434ff23e", "url_unittests": "025e3dfdb9f142c6161fc0f9541b66752233e28c", "views_unittests": "4d9ba61910328eb5759c6af795888eda1eaac7fe", "viz_unittests": "104704e9e5b1dab1fba809b9e79c87255583219b", "vr_common_unittests": "b8a8c31335ce510a574e039eac392c299d0b70fd", "vr_pixeltests": "8209a6668387366fa6a1a4077a1eff0b1cb3d9d2", "wm_unittests": "e41e6ae46787272c70f332826821981414d6880b", "wtf_unittests": "4290e041f8ca577eb42f95a6e47dbcaabcbc23a1"}}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmp5r6Zoc.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/tmphjKkuk.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: 35626 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/8918992067164676304 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/it8M2R7U/luci_context.835631442 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: swarm323-c4 SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 4395ff85e597a911 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-14 10:16:29,758 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmpANdRtW' 2019-03-14 10:16:29,758 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmpANdRtW' already exists! 2019-03-14 10:16:29,758 - root: [WARNING] task_output_dir existing content: [] 2019-03-14 10:16:29,758 - 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/tmphjKkuk.json -output-dir /b/swarming/w/ir/tmp/t/tmpANdRtW -task-summary-json /b/swarming/w/ir/tmp/t/tmp5r6Zoc.json [D2019-03-14T10:16:29.765069-07:00 19589 0 auth.go:1265] Minting a new token {"key":"luci_ctx/1da150f0ed2ec394ba8466907519fd065bf13cbfe5f6e6166657db0e5150fd8c", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-14T10:16:29.765280-07:00 19589 0 luci_ctx.go:138] POST http://127.0.0.1:34520/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/1da150f0ed2ec394ba8466907519fd065bf13cbfe5f6e6166657db0e5150fd8c", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-03-14T10:16:29.767092-07:00 19589 0 auth.go:1222] Token expires in 54m49.232929087s {"key":"luci_ctx/1da150f0ed2ec394ba8466907519fd065bf13cbfe5f6e6166657db0e5150fd8c", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 4396007c0ca9ce10: exit 0 Additional test environment: CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox CHROME_HEADLESS=1 G_SLICE=always-malloc LANG=en_US.UTF-8 NSS_DISABLE_ARENA_FREE_LIST=1 NSS_DISABLE_UNLOAD=1 TSAN_OPTIONS=symbolize=1 external_symbolizer_path=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer handle_abort=1 Command: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/iokH4a1x/output.json --no-sandbox IMPORTANT DEBUGGING NOTE: batches of tests are run inside their own process. For debugging a test inside a debugger, use the --gtest_filter=<your_test_name> flag along with --single-process-tests. Using sharding settings from environment. This is shard 0/1 Using 8 parallel jobs. [ RUN ] ProtocolHandlerTest.SendInitializeOnly [2441:2441:0314/092254.893382:42945110:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b80 with delay 0 [2441:2441:0314/092254.893751:42945476:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b80 [2441:2441:0314/092254.894067:42945792: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 } [2441:2441:0314/092254.894165:42945889:INFO:recurring-task.cc(55)] [Startup] Scheduling 7112 with a delay 500000, Now = 210919424 [2441:2441:0314/092254.894236:42945959:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c10 with delay 500 [2441:2441:0314/092254.894313:42946037:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000c10 [2441:2441:0314/092254.894739:42946463: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 (3 ms) [1/28] ProtocolHandlerTest.SendInitializeOnly (3 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [2441:2441:0314/092254.897267:42948993: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 (2 ms) [2/28] ProtocolHandlerTest.ReceiveTokenControlOnly (2 ms) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes [2441:2441:0314/092254.898087:42949813:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b10 with delay 0 [2441:2441:0314/092254.898198:42949919:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b40 with delay 0 [2441:2441:0314/092254.898268:42949989:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ac0 with delay 0 [2441:2441:0314/092254.898360:42950081:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b00 with delay 0 [2441:2441:0314/092254.898425:42950146:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ab0 with delay 0 [2441:2441:0314/092254.898526:42950248:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000af0 with delay 0 [2441:2441:0314/092254.898982:42950706:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b10 [2441:2441:0314/092254.899218:42950941: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 } [2441:2441:0314/092254.899304:42951028:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7400 with a delay 500000, Now = 210919424 [2441:2441:0314/092254.899387:42951109:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c60 with delay 500 [2441:2441:0314/092254.899461:42951184:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b40 [2441:2441:0314/092254.899547:42951281:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ac0 [2441:2441:0314/092254.899630:42951350:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b00 [2441:2441:0314/092254.899693:42951413:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ab0 [2441:2441:0314/092254.899756:42951475:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000af0 [2441:2441:0314/092254.899854:42951595:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [2441:2441:0314/092254.899995:42951737:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000c60 [2441:2441:0314/092254.900264:42951988:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [2441:2441:0314/092254.902327:42954057: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 (6 ms) [3/28] ProtocolHandlerTest.SendMultipleMessageTypes (6 ms) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage [2441:2441:0314/092254.904978:42956704:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } invalidation_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } } registration_status_message: { registration_status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } registration_status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } } registration_sync_request_message: { } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } [ OK ] ProtocolHandlerTest.IncomingCompositeMessage (2 ms) [4/28] ProtocolHandlerTest.IncomingCompositeMessage (2 ms) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage [2441:2441:0314/092254.906032:42957757: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 } } [2441:2441:0314/092254.906217:42957941: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" } [2441:2441:0314/092254.906427:42958150: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 } } [2441:2441:0314/092254.906673:42958395:ERROR:protocol-handler.cc(145)] Received invalid message: { header: { client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } [ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms) [5/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch [2441:2441:0314/092254.907648:42959374: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 } } [2441:2441:0314/092254.907893:42959618:ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } [ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms) [6/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch [2441:2441:0314/092254.908882:42960610:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 4 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.MinorVersionMismatch (1 ms) [7/28] ProtocolHandlerTest.MinorVersionMismatch (1 ms) [ RUN ] ProtocolHandlerTest.ConfigMessage [2441:2441:0314/092254.910863:42962589: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" } } [2441:2441:0314/092254.910975:42962699:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000a40 with delay 0 [2441:2441:0314/092254.911047:42962771:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000a40 [2441:2441:0314/092254.911216:42962940: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 } [2441:2441:0314/092254.911305:42963029:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7784 with a delay 500000, Now = 210919424 [2441:2441:0314/092254.911385:42963109:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000a50 with delay 500 [2441:2441:0314/092254.911462:42963185:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000a50 [2441:2441:0314/092254.911555:42963278:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 [ OK ] ProtocolHandlerTest.ConfigMessage (22 ms) [8/28] ProtocolHandlerTest.ConfigMessage (22 ms) [ RUN ] ProtocolHandlerTest.ErrorMessage [2441:2441:0314/092254.931920:42983647:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.ErrorMessage (1 ms) [9/28] ProtocolHandlerTest.ErrorMessage (1 ms) [ RUN ] ProtocolHandlerTest.TokenMismatch [2441:2441:0314/092254.932855:42984581:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.TokenMismatch (1 ms) [10/28] ProtocolHandlerTest.TokenMismatch (1 ms) [ RUN ] ProtocolHandlerTest.TokenMissing [2442:2442:0314/092254.897872:42949600:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b80 with delay 0 [2442:2442:0314/092254.897974:42949704:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b80 [2442:2442:0314/092254.898324:42950048: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 } [2442:2442:0314/092254.898413:42950137:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7112 with a delay 500000, Now = 210919424 [2442:2442:0314/092254.898512:42950246:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b90 with delay 500 [2442:2442:0314/092254.898604:42950328:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b90 [2442:2442:0314/092254.898745:42950470:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [2442:2442:0314/092254.898818:42950543:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (2 ms) [11/28] ProtocolHandlerTest.TokenMissing (2 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [2442:2442:0314/092254.899631:42951357:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b90 with delay 0 [2442:2442:0314/092254.899712:42951440:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b90 [2442:2442:0314/092254.899793:42951517:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 7400 with a delay 500000, Now = 210919424 [2442:2442:0314/092254.899864:42951587:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b80 with delay 500 [2442:2442:0314/092254.899944:42951667:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b80 [2442:2442:0314/092254.900132:42951858:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [2442:2442:0314/092254.900256:42951980: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 } [2442:2442:0314/092254.900421:42952144: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 } } [2442:2442:0314/092254.901842:42953567: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 } } } [2442:2442:0314/092254.902151:42953875:ERROR:protocol-handler.cc(323)] Tried to send invalid message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true is_trickle_restart: true } } } [ OK ] ProtocolHandlerTest.InvalidOutboundMessage (3 ms) [12/28] ProtocolHandlerTest.InvalidOutboundMessage (3 ms) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage [2442:2442:0314/092254.902930:42954655:INFO:protocol-handler.cc(139)] Incoming message: { } [2442:2442:0314/092254.903014:42954738:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [2442:2442:0314/092254.903090:42954812:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [13/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [ RUN ] RecurringTaskTest.PeriodicTask [2442:2442:0314/092254.903545:42955270:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -2032363896 with a delay 10000, Now = 0 [2442:2442:0314/092254.903627:42955350:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b04000009f0 with delay 10 [2442:2442:0314/092254.903698:42955421:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b04000009f0 [2442:2442:0314/092254.903775:42955498:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [2442:2442:0314/092254.903845:42955568:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 60000, Now = 10000 [2442:2442:0314/092254.903914:42955637:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b0400000a00 with delay 60 [2442:2442:0314/092254.903986:42955712:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x7b0400000a00 [2442:2442:0314/092254.904055:42955789:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [2442:2442:0314/092254.904130:42955871:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 60000, Now = 70000 [2442:2442:0314/092254.904213:42955936:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x7b04000009f0 with delay 60 [2442:2442:0314/092254.904279:42956000:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x7b04000009f0 [2442:2442:0314/092254.904364:42956085:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [2442:2442:0314/092254.904426:42956148:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 60000, Now = 130000 [2442:2442:0314/092254.904492:42956215:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x7b0400000a00 with delay 60 [2442:2442:0314/092254.904567:42956289:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x7b0400000a00 [2442:2442:0314/092254.904629:42956351:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [2442:2442:0314/092254.904692:42956414:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 60000, Now = 190000 [2442:2442:0314/092254.904756:42956478:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x7b04000009f0 with delay 60 [2442:2442:0314/092254.904819:42956541:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x7b04000009f0 [2442:2442:0314/092254.904881:42956602:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [2442:2442:0314/092254.904944:42956665:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 60000, Now = 250000 [2442:2442:0314/092254.905012:42956734:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x7b0400000a00 with delay 60 [2442:2442:0314/092254.905076:42956797:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x7b0400000a00 [2442:2442:0314/092254.905137:42956859:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [2442:2442:0314/092254.905199:42956920:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 60000, Now = 310000 [2442:2442:0314/092254.905274:42956995:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x7b04000009f0 with delay 60 [2442:2442:0314/092254.905334:42957054:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x7b04000009f0 [2442:2442:0314/092254.905392:42957113:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [2442:2442:0314/092254.905451:42957171:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 60000, Now = 370000 [2442:2442:0314/092254.905517:42957247:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x7b0400000a00 with delay 60 [2442:2442:0314/092254.905591:42957311:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x7b0400000a00 [2442:2442:0314/092254.905649:42957371:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (3 ms) [14/28] RecurringTaskTest.PeriodicTask (3 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [2442:2442:0314/092254.906344:42958068:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -2032363896 with a delay 10000, Now = 0 [2442:2442:0314/092254.906435:42958158:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b0400000a00 with delay 10 [2442:2442:0314/092254.906537:42958259:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b0400000a00 [2442:2442:0314/092254.906618:42958340:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [2442:2442:0314/092254.906683:42958404:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 50000, Now = 10000 [2442:2442:0314/092254.906758:42958480:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000009f0 with delay 50 [2442:2442:0314/092254.906825:42958565:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x7b04000009f0 [2442:2442:0314/092254.906908:42958630:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [2442:2442:0314/092254.906981:42958708:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 149000, Now = 60000 [2442:2442:0314/092254.907053:42958776:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x7b0400000a00 with delay 149 [2442:2442:0314/092254.907123:42958845:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x7b0400000a00 [2442:2442:0314/092254.907188:42958910:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [2442:2442:0314/092254.907252:42958973:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 248000, Now = 210000 [2442:2442:0314/092254.907320:42959042:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x7b04000009f0 with delay 248 [2442:2442:0314/092254.907388:42959111:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x7b04000009f0 [2442:2442:0314/092254.907455:42959176:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [2442:2442:0314/092254.907530:42959251:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 446000, Now = 460000 [2442:2442:0314/092254.907595:42959317:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x7b0400000a00 with delay 446 [2442:2442:0314/092254.907667:42959389:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x7b0400000a00 [2442:2442:0314/092254.907732:42959454:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [2442:2442:0314/092254.907795:42959520:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 842000, Now = 910000 [2442:2442:0314/092254.907864:42959586:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x7b04000009f0 with delay 842 [2442:2442:0314/092254.907937:42959659:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x7b04000009f0 [2442:2442:0314/092254.908005:42959727:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [2442:2442:0314/092254.908068:42959790:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 1040000, Now = 1760000 [2442:2442:0314/092254.908132:42959853:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x7b0400000a00 with delay 1040 [2442:2442:0314/092254.908206:42959927:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x7b0400000a00 [2442:2442:0314/092254.908280:42960001:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [2442:2442:0314/092254.908358:42960080:INFO:recurring-task.cc(55)] [Retry] Scheduling -2032363896 with a delay 1040000, Now = 2800000 [2442:2442:0314/092254.908420:42960140:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x7b04000009f0 with delay 1040 [2442:2442:0314/092254.908513:42960243:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x7b04000009f0 [2442:2442:0314/092254.908591:42960312:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms) [15/28] RecurringTaskTest.ExponentialBackoffTask (3 ms) [ RUN ] RecurringTaskTest.OneShotTask [2442:2442:0314/092254.909201:42960930:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -2032363968 with a delay 10000, Now = 0 [2442:2442:0314/092254.909281:42961005:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x7b04000009f0 with delay 10 [2442:2442:0314/092254.909355:42962040:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x7b04000009f0 [2442:2442:0314/092254.910392:42962115:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [2442:2442:0314/092254.910481:42962205:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -2032363968 with a delay 10000, Now = 10000 [2442:2442:0314/092254.910560:42962283:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000009f0 with delay 10 [2442:2442:0314/092254.910632:42962354:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x7b04000009f0 [2442:2442:0314/092254.910702:42962424:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (2 ms) [16/28] RecurringTaskTest.OneShotTask (2 ms) [ RUN ] ThrottleTest.ThrottlingScripted [2442:2442:0314/092254.911422:42963149:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x7b04000009f0 with delay 920 [2442:2442:0314/092254.911518:42963252:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.911713:42963437:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x7b04000009f0 with delay 45000 [2442:2442:0314/092254.912301:42964047:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7b04000009f0 [ OK ] ThrottleTest.ThrottlingScripted (1 ms) [17/28] ThrottleTest.ThrottlingScripted (1 ms) [ RUN ] ThrottleTest.ThrottlingStorm [2442:2442:0314/092254.912626:42964351:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x7b04000009f0 with delay 990 [2442:2442:0314/092254.912724:42964449:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.912801:42964523:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.912886:42964608:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.912955:42964677:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.913046:42964767:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.913114:42964835:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.913196:42964918:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.913263:42964984:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.913343:42965064:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.913409:42965130:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.913490:42965214:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.913568:42965290:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x7b0400000a00 with delay 54000 [2442:2442:0314/092254.914661:42966384:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.915581:42967303:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x7b0400000a00 with delay 1000 [2442:2442:0314/092254.915684:42967407:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.915765:42967487:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x7b0400000a00 with delay 1000 [2442:2442:0314/092254.915853:42967574:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.915920:42967641:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x7b0400000a00 with delay 1000 [2442:2442:0314/092254.916005:42967725:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.916069:42967789:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x7b0400000a00 with delay 1000 [2442:2442:0314/092254.916145:42967866:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.916209:42967930:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x7b0400000a00 with delay 1000 [2442:2442:0314/092254.916287:42968028:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.916374:42968096:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x7b0400000a00 with delay 1000 [2442:2442:0314/092254.916454:42968174:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.916519:42968250:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x7b04000009f0 with delay 54000 [2442:2442:0314/092254.917580:42969302:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.917660:42969381:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.917742:42969462:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.917807:42969527:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.917886:42969606:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.917971:42969692:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.918057:42969778:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.918124:42969846:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.918219:42969940:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.918282:42970003:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.918361:42970081:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.918422:42970143:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.918500:42970222:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.918572:42970293:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x7b0400000a00 with delay 54000 [2442:2442:0314/092254.920434:42972155:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.920512:42972242:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x7b0400000a00 with delay 1000 [2442:2442:0314/092254.920603:42972324:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.920668:42972389:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x7b0400000a00 with delay 1000 [2442:2442:0314/092254.920748:42972469:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.920813:42972534:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x7b0400000a00 with delay 1000 [2442:2442:0314/092254.920892:42972613:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.920957:42972678:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x7b0400000a00 with delay 1000 [2442:2442:0314/092254.921044:42972765:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.921108:42972828:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x7b0400000a00 with delay 1000 [2442:2442:0314/092254.921183:42972923:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.921265:42972986:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x7b0400000a00 with delay 1000 [2442:2442:0314/092254.921343:42973064:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x7b0400000a00 [2442:2442:0314/092254.921405:42973128:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x7b04000009f0 with delay 54000 [2442:2442:0314/092254.922476:42974197:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.922559:42974280:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.922639:42974360:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.922702:42974423:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.922780:42974500:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.922847:42974568:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.922946:42974667:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.923044:42974766:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.923124:42974846:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.923188:42974909:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.923279:42975018:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.923361:42975082:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x7b04000009f0 with delay 1000 [2442:2442:0314/092254.923441:42975162:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x7b04000009f0 [2442:2442:0314/092254.923504:42975227:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x7b0400000a00 with delay 54000 [2442:2442:0314/092254.925530:42977260:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x7b0400000a00 [ OK ] ThrottleTest.ThrottlingStorm (13 ms) [18/28] ThrottleTest.ThrottlingStorm (13 ms) [ RUN ] InvalidationClientImplTest.Start [2439:2439:0314/092254.875434:42927173:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c80 with delay 0 [2439:2439:0314/092254.875768:42927493:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2439:2439:0314/092254.876333:42928058:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e50 with delay 0 [2439:2439:0314/092254.876413:42928136:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c80 [2439:2439:0314/092254.876493:42928224:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e50 [2439:2439:0314/092254.876654:42928377:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2439:2439:0314/092254.876777:42928499:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ea0 with delay 0 [2439:2439:0314/092254.876860:42928582:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ea0 [2439:2439:0314/092254.876928:42928651:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2439:2439:0314/092254.877024:42928748:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e50 with delay 0 [2439:2439:0314/092254.877116:42928838:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e50 [2439:2439:0314/092254.877191:42928915:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2439:2439:0314/092254.877279:42929001:INFO:recurring-task.cc(55)] [Startup] Scheduling 7112 with a delay 0, Now = 210919424 [2439:2439:0314/092254.877349:42929071:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ea0 with delay 0 [2439:2439:0314/092254.877433:42929155:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ea0 [2439:2439:0314/092254.877605:42929340:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "6289558783012149746" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2439:2439:0314/092254.877709:42929439:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7496 with a delay 500000, Now = 210919424 [2439:2439:0314/092254.877785:42929508:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e50 with delay 500 [2439:2439:0314/092254.877854:42929580:INFO:recurring-task.cc(55)] [Retry] Scheduling 7112 with a delay 60000000, Now = 210919424 [2439:2439:0314/092254.877924:42929646:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e10 with delay 60000 [2439:2439:0314/092254.877998:42929721:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e50 [2439:2439:0314/092254.878069:42929791:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.879447:42931172:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.879859:42931582: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: "6289558783012149746" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2439:2439:0314/092254.880137:42931862:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e50 with delay 0 [2439:2439:0314/092254.880215:42931948:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e50 [2439:2439:0314/092254.880531:42932256:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "6289558783012149746" 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" } } [2439:2439:0314/092254.880650:42932374:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "6289558783012149746" [2439:2439:0314/092254.880730:42932454:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2439:2439:0314/092254.880807:42932530:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [2439:2439:0314/092254.880879:42932601:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e90 with delay 1200000 [2439:2439:0314/092254.880957:42932679:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2439:2439:0314/092254.881207:42932931:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2439:2439:0314/092254.881285:42933009:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424 [2439:2439:0314/092254.881368:42933090:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ea0 with delay 0 [2439:2439:0314/092254.881482:42933216: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 [2439:2439:0314/092254.881617:42933339:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ea0 [2439:2439:0314/092254.881760:42933481:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ec0 with delay 0 [2439:2439:0314/092254.881834:42933557:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424 [2439:2439:0314/092254.881939:42933662:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c80 with delay 10000 [2439:2439:0314/092254.882018:42933741:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ec0 [2439:2439:0314/092254.882087:42933810:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (8 ms) [19/28] InvalidationClientImplTest.Start (8 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [2439:2439:0314/092254.883229:42934953:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e70 with delay 0 [2439:2439:0314/092254.883339:42935061: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 [2439:2439:0314/092254.884262:42935987:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e80 with delay 0 [2439:2439:0314/092254.884391:42936114:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2439:2439:0314/092254.884895:42936620:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ee0 with delay 0 [2439:2439:0314/092254.884977:42936704:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e80 [2439:2439:0314/092254.885059:42936781:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ee0 [2439:2439:0314/092254.885204:42936928:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2439:2439:0314/092254.885324:42937047:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f20 with delay 0 [2439:2439:0314/092254.885402:42937125:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f20 [2439:2439:0314/092254.885471:42937194:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2439:2439:0314/092254.885552:42937276:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ee0 with delay 0 [2439:2439:0314/092254.885629:42937351:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ee0 [2439:2439:0314/092254.885702:42937425:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2439:2439:0314/092254.885777:42937500:INFO:recurring-task.cc(55)] [Startup] Scheduling 7592 with a delay 0, Now = 210919424 [2439:2439:0314/092254.885848:42937571:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f20 with delay 0 [2439:2439:0314/092254.885916:42937638:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f20 [2439:2439:0314/092254.886063:42937786:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-4409251806616085833" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2439:2439:0314/092254.886143:42937867:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7112 with a delay 500000, Now = 210919424 [2439:2439:0314/092254.886214:42937943:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ee0 with delay 500 [2439:2439:0314/092254.886296:42938024:INFO:recurring-task.cc(55)] [Retry] Scheduling 7592 with a delay 60000000, Now = 210919424 [2439:2439:0314/092254.886378:42938102:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f00 with delay 60000 [2439:2439:0314/092254.886453:42938175:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ee0 [2439:2439:0314/092254.886530:42938253:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.886628:42938350:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.886947:42938669: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: "-4409251806616085833" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2439:2439:0314/092254.887140:42938864:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ee0 with delay 0 [2439:2439:0314/092254.887214:42938937:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ee0 [2439:2439:0314/092254.887473:42939197:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-4409251806616085833" 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" } } [2439:2439:0314/092254.887583:42939306:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-4409251806616085833" [2439:2439:0314/092254.887666:42939390:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2439:2439:0314/092254.887753:42939476:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1576 with a delay 1200000000, Now = 211419424 [2439:2439:0314/092254.887828:42939550:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f10 with delay 1200000 [2439:2439:0314/092254.887900:42939622:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2439:2439:0314/092254.888156:42939879:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2439:2439:0314/092254.888238:42939963:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424 [2439:2439:0314/092254.888331:42940055:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f20 with delay 0 [2439:2439:0314/092254.888457:42940187: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 [2439:2439:0314/092254.888565:42940288:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f20 [2439:2439:0314/092254.888700:42940426:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f40 with delay 0 [2439:2439:0314/092254.888781:42940504:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424 [2439:2439:0314/092254.888851:42940574:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e80 with delay 10000 [2439:2439:0314/092254.888921:42940644:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f40 [2439:2439:0314/092254.888988:42940710:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2439:2439:0314/092254.889099:42940825:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f40 with delay 0 [2439:2439:0314/092254.889173:42940896:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000f40 [2439:2439:0314/092254.889271:42940994:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [2439:2439:0314/092254.889364:42941086:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [2439:2439:0314/092254.889453:42941175:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [2439:2439:0314/092254.889621:42941348:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7112 with a delay 500000, Now = 211469424 [2439:2439:0314/092254.889696:42941419:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f20 with delay 500 [2439:2439:0314/092254.889769:42941492:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7784 with a delay 60000000, Now = 211469424 [2439:2439:0314/092254.889852:42941575:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f30 with delay 60000 [2439:2439:0314/092254.889931:42941671:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f20 [2439:2439:0314/092254.890029:42941753:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.890123:42941846:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.890194:42941917:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2439:2439:0314/092254.891984:42943708: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 } } } [2439:2439:0314/092254.892162:42943886:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.892293:42944036:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7b0400000f20 with delay 0 [2439:2439:0314/092254.892392:42944115:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f20 [2439:2439:0314/092254.892920:42944645: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 } } } } [2439:2439:0314/092254.893095:42944820: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 [2439:2439:0314/092254.893298:42945023:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [2439:2439:0314/092254.893505:42945238:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [2439:2439:0314/092254.893710:42945433:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [2439:2439:0314/092254.893945:42945669:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000e80 [ OK ] InvalidationClientImplTest.Register (11 ms) [21/28] InvalidationClientImplTest.Register (11 ms) [ RUN ] InvalidationClientImplTest.Invalidations [2439:2439:0314/092254.895436:42947161:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000dc0 with delay 0 [2439:2439:0314/092254.895558:42947283:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2439:2439:0314/092254.896088:42947813:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c30 with delay 0 [2439:2439:0314/092254.896171:42947893:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000dc0 [2439:2439:0314/092254.896238:42947960:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c30 [2439:2439:0314/092254.896396:42948119:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2439:2439:0314/092254.896525:42948248:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f40 with delay 0 [2439:2439:0314/092254.896603:42948331:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f40 [2439:2439:0314/092254.896678:42948406:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2439:2439:0314/092254.896758:42948482:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c30 with delay 0 [2439:2439:0314/092254.896829:42948551:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c30 [2439:2439:0314/092254.896896:42948618:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2439:2439:0314/092254.896970:42948694:INFO:recurring-task.cc(55)] [Startup] Scheduling 7688 with a delay 0, Now = 210919424 [2439:2439:0314/092254.897040:42948763:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f40 with delay 0 [2439:2439:0314/092254.897113:42948837:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f40 [2439:2439:0314/092254.897257:42948981:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "2755904445708456254" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2439:2439:0314/092254.897335:42949060:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7976 with a delay 500000, Now = 210919424 [2439:2439:0314/092254.897406:42949129:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c30 with delay 500 [2439:2439:0314/092254.897475:42949198:INFO:recurring-task.cc(55)] [Retry] Scheduling 7688 with a delay 60000000, Now = 210919424 [2439:2439:0314/092254.897556:42949280:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ba0 with delay 60000 [2439:2439:0314/092254.897642:42949364:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000c30 [2439:2439:0314/092254.897713:42949436:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.897796:42949519:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.898082:42949806: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: "2755904445708456254" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2439:2439:0314/092254.898279:42950003:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c30 with delay 0 [2439:2439:0314/092254.898356:42950080:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000c30 [2439:2439:0314/092254.898629:42950353:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "2755904445708456254" 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" } } [2439:2439:0314/092254.898728:42950452:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "2755904445708456254" [2439:2439:0314/092254.898807:42950531:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2439:2439:0314/092254.898883:42950612:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [2439:2439:0314/092254.898965:42950688:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ee0 with delay 1200000 [2439:2439:0314/092254.899038:42950763:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2439:2439:0314/092254.899265:42950989:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2439:2439:0314/092254.899352:42951075:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1288 with a delay 0, Now = 211419424 [2439:2439:0314/092254.899422:42951145:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f40 with delay 0 [2439:2439:0314/092254.899543:42951267: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 [2439:2439:0314/092254.899631:42951354:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f40 [2439:2439:0314/092254.899775:42951498:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f70 with delay 0 [2439:2439:0314/092254.899859:42951582:INFO:recurring-task.cc(55)] [Retry] Scheduling 1288 with a delay 10000000, Now = 211419424 [2439:2439:0314/092254.899935:42951659:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000dc0 with delay 10000 [2439:2439:0314/092254.900006:42951729:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f70 [2439:2439:0314/092254.900073:42951796:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2439:2439:0314/092254.900166:42951889:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.900290:42952044:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f70 with delay 0 [2439:2439:0314/092254.900392:42952114:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000f70 [2439:2439:0314/092254.900844:42952568: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 } } } [2439:2439:0314/092254.901008:42952732: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 [2439:2439:0314/092254.902444:42954168: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" } [2439:2439:0314/092254.902680:42954404:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [2439:2439:0314/092254.902875:42954598:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [2439:2439:0314/092254.903024:42954747:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400000f70 with delay 0 [2439:2439:0314/092254.903100:42954823:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400000f40 with delay 0 [2439:2439:0314/092254.903184:42954911:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400000f50 with delay 0 [2439:2439:0314/092254.903262:42954985:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400000f70 [2439:2439:0314/092254.903356:42955079:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 7976 with a delay 500000, Now = 211519424 [2439:2439:0314/092254.903443:42955166:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x7b0400000c30 with delay 500 [2439:2439:0314/092254.903526:42955249:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400000f40 [2439:2439:0314/092254.903608:42955333:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x7b0400000f50 [2439:2439:0314/092254.903697:42955419:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x7b0400000c30 [2439:2439:0314/092254.903767:42955493:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.903860:42955583:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.903935:42955657:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2439:2439:0314/092254.904409:42956134: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 (10 ms) [22/28] InvalidationClientImplTest.Invalidations (10 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [2439:2439:0314/092254.905504:42957238:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000eb0 with delay 0 [2439:2439:0314/092254.905641:42957365:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2439:2439:0314/092254.906045:42957769:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000d10 with delay 0 [2439:2439:0314/092254.906121:42957845:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000eb0 [2439:2439:0314/092254.906195:42957916:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000d10 [2439:2439:0314/092254.906332:42958055:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2439:2439:0314/092254.906447:42958171:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f20 with delay 0 [2439:2439:0314/092254.906535:42958257:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f20 [2439:2439:0314/092254.906605:42958333:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2439:2439:0314/092254.906682:42958404:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000d10 with delay 0 [2439:2439:0314/092254.906753:42958476:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000d10 [2439:2439:0314/092254.906821:42958544:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2439:2439:0314/092254.906896:42958619:INFO:recurring-task.cc(55)] [Startup] Scheduling 7592 with a delay 0, Now = 210919424 [2439:2439:0314/092254.906972:42958694:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f20 with delay 0 [2439:2439:0314/092254.907042:42958764:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f20 [2439:2439:0314/092254.907183:42958906:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "5083917914704019424" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2439:2439:0314/092254.907260:42958983:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8456 with a delay 500000, Now = 210919424 [2439:2439:0314/092254.907342:42959065:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000d10 with delay 500 [2439:2439:0314/092254.907412:42959134:INFO:recurring-task.cc(55)] [Retry] Scheduling 7592 with a delay 60000000, Now = 210919424 [2439:2439:0314/092254.907481:42959204:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000d40 with delay 60000 [2439:2439:0314/092254.907573:42959295:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000d10 [2439:2439:0314/092254.907649:42959372:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.907739:42959462:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.908039:42959763: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: "5083917914704019424" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2439:2439:0314/092254.908220:42959944:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000d10 with delay 0 [2439:2439:0314/092254.908294:42960038:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000d10 [2439:2439:0314/092254.908582:42960307:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "5083917914704019424" 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" } } [2439:2439:0314/092254.908694:42960418:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "5083917914704019424" [2439:2439:0314/092254.908782:42960506:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2439:2439:0314/092254.908859:42960584:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [2439:2439:0314/092254.908932:42960656:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c00 with delay 1200000 [2439:2439:0314/092254.909013:42960736:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2439:2439:0314/092254.909257:42960981:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2439:2439:0314/092254.909335:42961057:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424 [2439:2439:0314/092254.909407:42961130:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f20 with delay 0 [2439:2439:0314/092254.909518:42961251: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 [2439:2439:0314/092254.909609:42961337:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f20 [2439:2439:0314/092254.909743:42961468:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c20 with delay 0 [2439:2439:0314/092254.909823:42961546:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424 [2439:2439:0314/092254.909898:42961622:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000eb0 with delay 10000 [2439:2439:0314/092254.909969:42961691:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000c20 [2439:2439:0314/092254.910036:42961759:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2439:2439:0314/092254.910117:42961843:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.910217:42961941:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000c20 with delay 0 [2439:2439:0314/092254.910290:42962012:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000c20 [2439:2439:0314/092254.910562:42962290: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 } } [2439:2439:0314/092254.910726:42962450: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 [2439:2439:0314/092254.910810:42962533:INFO:protocol-handler.cc(294)] Adding subtree: { } [2439:2439:0314/092254.910883:42962607:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 8456 with a delay 500000, Now = 211469424 [2439:2439:0314/092254.910960:42962683:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f20 with delay 500 [2439:2439:0314/092254.911033:42962757:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [2439:2439:0314/092254.911473:42963198: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 } [2439:2439:0314/092254.911599:42963323:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f20 [2439:2439:0314/092254.911678:42963401:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.911811:42963534:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.911893:42963617:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2439:2439:0314/092254.913378:42965103: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 } } [2439:2439:0314/092254.914744:42966469:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000eb0 [ OK ] InvalidationClientImplTest.ServerRequests (11 ms) [23/28] InvalidationClientImplTest.ServerRequests (11 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [2439:2439:0314/092254.916240:42967965:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b50 with delay 0 [2439:2439:0314/092254.916369:42968093:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2439:2439:0314/092254.916833:42968559:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000d10 with delay 0 [2439:2439:0314/092254.916911:42968635:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b50 [2439:2439:0314/092254.916980:42968702:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000d10 [2439:2439:0314/092254.917118:42968847:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2439:2439:0314/092254.917237:42968961:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ae0 with delay 0 [2439:2439:0314/092254.917313:42969035:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ae0 [2439:2439:0314/092254.917380:42969103:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2439:2439:0314/092254.917452:42969176:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000d10 with delay 0 [2439:2439:0314/092254.917522:42969254:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000d10 [2439:2439:0314/092254.917605:42969329:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2439:2439:0314/092254.917688:42969414:INFO:recurring-task.cc(55)] [Startup] Scheduling 7976 with a delay 0, Now = 210919424 [2439:2439:0314/092254.917770:42969493:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ae0 with delay 0 [2439:2439:0314/092254.917841:42969563:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000ae0 [2439:2439:0314/092254.917984:42969707:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-5255074036406776126" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2439:2439:0314/092254.918062:42969785:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7592 with a delay 500000, Now = 210919424 [2439:2439:0314/092254.918133:42969858:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000d10 with delay 500 [2439:2439:0314/092254.918203:42969926:INFO:recurring-task.cc(55)] [Retry] Scheduling 7976 with a delay 60000000, Now = 210919424 [2439:2439:0314/092254.918273:42969996:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ad0 with delay 60000 [2439:2439:0314/092254.918348:42970070:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000d10 [2439:2439:0314/092254.918417:42970140:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.918500:42970223:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.918803:42970526: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: "-5255074036406776126" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2439:2439:0314/092254.918980:42970703:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000d10 with delay 0 [2439:2439:0314/092254.919059:42970782:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000d10 [2439:2439:0314/092254.919318:42971041:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-5255074036406776126" 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" } } [2439:2439:0314/092254.919420:42971147:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-5255074036406776126" [2439:2439:0314/092254.919499:42971223:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2439:2439:0314/092254.919583:42971307:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [2439:2439:0314/092254.919664:42971388:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b30 with delay 1200000 [2439:2439:0314/092254.919737:42971485:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2439:2439:0314/092254.919980:42971704:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2439:2439:0314/092254.920072:42971795:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424 [2439:2439:0314/092254.920144:42971867:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ae0 with delay 0 [2439:2439:0314/092254.920258:42971981: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 [2439:2439:0314/092254.920367:42972090:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000ae0 [2439:2439:0314/092254.920501:42972225:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b04000009e0 with delay 0 [2439:2439:0314/092254.920588:42972311:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424 [2439:2439:0314/092254.920665:42972387:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b50 with delay 10000 [2439:2439:0314/092254.920736:42972458:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b04000009e0 [2439:2439:0314/092254.920803:42972526:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2439:2439:0314/092254.920888:42972611:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.920983:42972709:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b04000009e0 with delay 0 [2439:2439:0314/092254.921057:42972780:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b04000009e0 [2439:2439:0314/092254.921306:42973033: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" } } [2439:2439:0314/092254.921447:42973170: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 [2439:2439:0314/092254.921523:42973256:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [2439:2439:0314/092254.921792:42973515:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000b50 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (8 ms) [24/28] InvalidationClientImplTest.IncomingErrorMessage (8 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [2439:2439:0314/092254.924013:42975739:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000d90 with delay 0 [2439:2439:0314/092254.924127:42975853:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2439:2439:0314/092254.924668:42976392:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e70 with delay 0 [2439:2439:0314/092254.924745:42976471:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000d90 [2439:2439:0314/092254.924822:42976544:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e70 [2439:2439:0314/092254.924962:42976685:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2439:2439:0314/092254.925075:42976799:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f50 with delay 0 [2439:2439:0314/092254.925153:42976876:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f50 [2439:2439:0314/092254.925222:42976944:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2439:2439:0314/092254.925294:42977017:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e70 with delay 0 [2439:2439:0314/092254.925363:42977085:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e70 [2439:2439:0314/092254.925429:42977152:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2439:2439:0314/092254.925512:42977248:INFO:recurring-task.cc(55)] [Startup] Scheduling 7688 with a delay 0, Now = 210919424 [2439:2439:0314/092254.925595:42977318:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000f50 with delay 0 [2439:2439:0314/092254.925670:42977393:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000f50 [2439:2439:0314/092254.925823:42977547:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-4670124170563131999" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2439:2439:0314/092254.925904:42977627:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7976 with a delay 500000, Now = 210919424 [2439:2439:0314/092254.925977:42977699:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e70 with delay 500 [2439:2439:0314/092254.926045:42977768:INFO:recurring-task.cc(55)] [Retry] Scheduling 7688 with a delay 60000000, Now = 210919424 [2439:2439:0314/092254.926116:42977839:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c30 with delay 60000 [2439:2439:0314/092254.926193:42977916:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e70 [2439:2439:0314/092254.926263:42977986:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.926350:42978072:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.926649:42978373: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: "-4670124170563131999" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2439:2439:0314/092254.926853:42978577:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e70 with delay 0 [2439:2439:0314/092254.926934:42978657:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e70 [2439:2439:0314/092254.927189:42978913:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-4670124170563131999" 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" } } [2439:2439:0314/092254.927295:42979021:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-4670124170563131999" [2439:2439:0314/092254.927375:42979099:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2439:2439:0314/092254.927456:42979180:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [2439:2439:0314/092254.927529:42979262:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f40 with delay 1200000 [2439:2439:0314/092254.927614:42979339:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2439:2439:0314/092254.927839:42979563:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2439:2439:0314/092254.927917:42979640:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424 [2439:2439:0314/092254.927986:42979713:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f50 with delay 0 [2439:2439:0314/092254.928103:42979827: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 [2439:2439:0314/092254.928187:42979911:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f50 [2439:2439:0314/092254.928334:42980057:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000f60 with delay 0 [2439:2439:0314/092254.928417:42980140:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424 [2439:2439:0314/092254.928489:42980213:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000d90 with delay 10000 [2439:2439:0314/092254.928569:42980292:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000f60 [2439:2439:0314/092254.928638:42980367:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2439:2439:0314/092254.928728:42980451:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f60 with delay 0 [2439:2439:0314/092254.928797:42980520:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000f60 [2439:2439:0314/092254.928895:42980618:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [2439:2439:0314/092254.929014:42980738:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7976 with a delay 500000, Now = 211469424 [2439:2439:0314/092254.929084:42980807:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f50 with delay 500 [2439:2439:0314/092254.929159:42980882:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7112 with a delay 60000000, Now = 211469424 [2439:2439:0314/092254.929227:42980950:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000f70 with delay 60000 [2439:2439:0314/092254.929309:42981032:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f50 [2439:2439:0314/092254.929379:42981101:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.929464:42981187:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.929544:42981267:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2439:2439:0314/092254.929842:42981566: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 } } } [2439:2439:0314/092254.929986:42981710:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.930094:42981818:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x7b0400000f50 with delay 0 [2439:2439:0314/092254.930167:42981893:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000f50 [2439:2439:0314/092254.930412:42982136: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" } } [2439:2439:0314/092254.930554:42982278: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 [2439:2439:0314/092254.930634:42982363:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [2439:2439:0314/092254.930796:42982519:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [2439:2439:0314/092254.931038:42982762:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000d90 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (8 ms) [25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (8 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [2439:2439:0314/092254.933337:42985063:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c20 with delay 0 [2439:2439:0314/092254.933451:42985173:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2439:2439:0314/092254.933838:42985563:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b50 with delay 0 [2439:2439:0314/092254.933912:42985633:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c20 [2439:2439:0314/092254.933978:42985700:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b50 [2439:2439:0314/092254.934114:42985838:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2439:2439:0314/092254.934224:42985947:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e20 with delay 0 [2439:2439:0314/092254.934318:42986040:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e20 [2439:2439:0314/092254.934385:42986109:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2439:2439:0314/092254.934456:42986180:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b50 with delay 0 [2439:2439:0314/092254.934525:42986256:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b50 [2439:2439:0314/092254.934604:42986327:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2439:2439:0314/092254.934685:42986409:INFO:recurring-task.cc(55)] [Startup] Scheduling 7880 with a delay 0, Now = 210919424 [2439:2439:0314/092254.934764:42986487:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e20 with delay 0 [2439:2439:0314/092254.934834:42986556:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e20 [2439:2439:0314/092254.934976:42986700:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-7342268308298467698" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2439:2439:0314/092254.935054:42986778:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 7688 with a delay 500000, Now = 210919424 [2439:2439:0314/092254.935126:42986851:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b50 with delay 500 [2439:2439:0314/092254.935197:42986920:INFO:recurring-task.cc(55)] [Retry] Scheduling 7880 with a delay 60000000, Now = 210919424 [2439:2439:0314/092254.935265:42986996:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c50 with delay 60000 [2439:2439:0314/092254.935349:42987072:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b50 [2439:2439:0314/092254.935430:42987153:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.935516:42987266:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.935842:42987565: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: "-7342268308298467698" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2439:2439:0314/092254.936021:42987745:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b50 with delay 0 [2439:2439:0314/092254.936095:42987818:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b50 [2439:2439:0314/092254.936368:42988092:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-7342268308298467698" 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" } } [2439:2439:0314/092254.936471:42988195:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-7342268308298467698" [2439:2439:0314/092254.936561:42988285:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2439:2439:0314/092254.936643:42988373:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 2024 with a delay 1200000000, Now = 211419424 [2439:2439:0314/092254.936721:42988445:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000ee0 with delay 1200000 [2439:2439:0314/092254.936798:42988521:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2439:2439:0314/092254.937035:42988759:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2439:2439:0314/092254.937112:42988834:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424 [2439:2439:0314/092254.937185:42988909:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e20 with delay 0 [2439:2439:0314/092254.937300:42989024: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 [2439:2439:0314/092254.937380:42989104:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000e20 [2439:2439:0314/092254.937508:42989231:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000a50 with delay 0 [2439:2439:0314/092254.937598:42989322:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424 [2439:2439:0314/092254.937672:42989396:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c20 with delay 10000 [2439:2439:0314/092254.937746:42989470:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000a50 [2439:2439:0314/092254.937814:42989559:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2439:2439:0314/092254.937921:42989644:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000a50 with delay 0 [2439:2439:0314/092254.937993:42989717:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000a50 [2439:2439:0314/092254.938091:42989815:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [2439:2439:0314/092254.938217:42989940:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 7688 with a delay 500000, Now = 211469424 [2439:2439:0314/092254.938298:42990021:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000e20 with delay 500 [2439:2439:0314/092254.938371:42990094:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 7496 with a delay 60000000, Now = 211469424 [2439:2439:0314/092254.938443:42990166:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000af0 with delay 60000 [2439:2439:0314/092254.938522:42990254:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x7b0400000e20 [2439:2439:0314/092254.938601:42990326:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.938692:42990418:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.938765:42990488:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2439:2439:0314/092254.939065:42990789: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 } } } [2439:2439:0314/092254.939317:42991040:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000c20 [2439:2439:0314/092254.939957:42991680:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7b0400000c50 [2439:2439:0314/092254.940032:42991753:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x7b0400000af0 [2439:2439:0314/092254.940142:42991876: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 [2439:2439:0314/092254.940228:42991952:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [2439:2439:0314/092254.940405:42992128: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 } [2439:2439:0314/092254.940487:42992213:INFO:recurring-task.cc(55)] [Send-info] Scheduling 7688 with a delay 500000, Now = 271469424 [2439:2439:0314/092254.940568:42992291:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7b0400000c50 with delay 500 [2439:2439:0314/092254.940657:42992378:INFO:recurring-task.cc(55)] [Retry] Scheduling 7496 with a delay 60000000, Now = 271469424 [2439:2439:0314/092254.940745:42992467:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x7b0400000c20 with delay 60000 [2439:2439:0314/092254.940819:42992542:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x7b0400000c50 [2439:2439:0314/092254.940892:42992616:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.940983:42992707:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.941055:42992779:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2439:2439:0314/092254.941383:42993109: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 (12 ms) [26/28] InvalidationClientImplTest.NetworkTimeouts (12 ms) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary [2439:2439:0314/092254.943863:42995590:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000e30 with delay 0 [2439:2439:0314/092254.943979:42995704:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2439:2439:0314/092254.944389:42996114:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b10 with delay 0 [2439:2439:0314/092254.944484:42996207:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000e30 [2439:2439:0314/092254.944572:42996295:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b10 [2439:2439:0314/092254.944717:42996441:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2439:2439:0314/092254.944837:42996561:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000af0 with delay 0 [2439:2439:0314/092254.944916:42996639:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000af0 [2439:2439:0314/092254.944986:42996710:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2439:2439:0314/092254.945058:42996784:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b10 with delay 0 [2439:2439:0314/092254.945130:42996854:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b10 [2439:2439:0314/092254.945206:42996930:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2439:2439:0314/092254.945282:42997005:INFO:recurring-task.cc(55)] [Startup] Scheduling 8456 with a delay 0, Now = 210919424 [2439:2439:0314/092254.945355:42997079:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000af0 with delay 0 [2439:2439:0314/092254.945425:42997148:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000af0 [2439:2439:0314/092254.945576:42997300:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-2996750511057448319" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2439:2439:0314/092254.945661:42997384:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8072 with a delay 500000, Now = 210919424 [2439:2439:0314/092254.945733:42997458:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b10 with delay 500 [2439:2439:0314/092254.945805:42997529:INFO:recurring-task.cc(55)] [Retry] Scheduling 8456 with a delay 60000000, Now = 210919424 [2439:2439:0314/092254.945876:42997599:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000dd0 with delay 60000 [2439:2439:0314/092254.945950:42997672:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b10 [2439:2439:0314/092254.946016:42997743:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.946100:42997823:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.946415:42998140: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: "-2996750511057448319" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2439:2439:0314/092254.946610:42998352:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b10 with delay 0 [2439:2439:0314/092254.946726:42998454:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b10 [2439:2439:0314/092254.946998:42998722:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-2996750511057448319" 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" } } [2439:2439:0314/092254.947098:42998822:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-2996750511057448319" [2439:2439:0314/092254.947181:42998904:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2439:2439:0314/092254.947256:42998980:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424 [2439:2439:0314/092254.947329:42999052:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e20 with delay 1200000 [2439:2439:0314/092254.947403:42999126:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2439:2439:0314/092254.947635:42999365:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2439:2439:0314/092254.947719:42999447:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424 [2439:2439:0314/092254.947808:42999531:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000af0 with delay 0 [2439:2439:0314/092254.947917:42999639: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 [2439:2439:0314/092254.947999:42999721:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000af0 [2439:2439:0314/092254.948145:42999875:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000a50 with delay 0 [2439:2439:0314/092254.948230:42999953:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424 [2439:2439:0314/092254.948303:43000041:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000e30 with delay 10000 [2439:2439:0314/092254.948391:43000116:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000a50 [2439:2439:0314/092254.948462:43000185:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2439:2439:0314/092254.948553:43000278:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.948650:43000380:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x7b0400000a50 with delay 0 [2439:2439:0314/092254.948730:43000457:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x7b0400000a50 [2439:2439:0314/092254.948922:43000645: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" } } [2439:2439:0314/092254.949131:43000853:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000e30 [2439:2439:0314/092254.949791:43001516: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 (7 ms) [27/28] InvalidationClientImplTest.NoRegistrationSummary (7 ms) [ RUN ] InvalidationClientImplTest.Heartbeats [2439:2439:0314/092254.950804:43002531:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000c90 with delay 0 [2439:2439:0314/092254.950919:43002644:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [2439:2439:0314/092254.951309:43003034:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b70 with delay 0 [2439:2439:0314/092254.951390:43003113:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000c90 [2439:2439:0314/092254.951460:43003182:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b70 [2439:2439:0314/092254.951609:43003333:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [2439:2439:0314/092254.951730:43003454:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000af0 with delay 0 [2439:2439:0314/092254.951807:43003530:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000af0 [2439:2439:0314/092254.951875:43003611:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [2439:2439:0314/092254.951960:43003682:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b70 with delay 0 [2439:2439:0314/092254.952027:43003749:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000b70 [2439:2439:0314/092254.952093:43003815:INFO:invalidation-client-core.cc(351)] Starting with no previous state [2439:2439:0314/092254.952170:43003893:INFO:recurring-task.cc(55)] [Startup] Scheduling 7784 with a delay 0, Now = 210919424 [2439:2439:0314/092254.952260:43003984:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000af0 with delay 0 [2439:2439:0314/092254.952352:43004075:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x7b0400000af0 [2439:2439:0314/092254.952498:43004222:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-1682619058771454986" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [2439:2439:0314/092254.952595:43004320:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 8456 with a delay 500000, Now = 210919424 [2439:2439:0314/092254.952673:43004397:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000b70 with delay 500 [2439:2439:0314/092254.952746:43004470:INFO:recurring-task.cc(55)] [Retry] Scheduling 7784 with a delay 60000000, Now = 210919424 [2439:2439:0314/092254.952815:43004538:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x7b0400000ac0 with delay 60000 [2439:2439:0314/092254.952892:43004615:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b70 [2439:2439:0314/092254.952962:43004686:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.953056:43004780:INFO:invalidation-client-core.cc(488)] Return client token = "" [2439:2439:0314/092254.953419:43005143: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: "-1682619058771454986" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [2439:2439:0314/092254.953610:43005334:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b70 with delay 0 [2439:2439:0314/092254.953713:43005437:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b70 [2439:2439:0314/092254.953970:43005695:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-1682619058771454986" 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" } } [2439:2439:0314/092254.954076:43005801:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-1682619058771454986" [2439:2439:0314/092254.954163:43005888:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [2439:2439:0314/092254.954241:43005968:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 1688 with a delay 1200000000, Now = 211419424 [2439:2439:0314/092254.954317:43006041:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000a50 with delay 1200000 [2439:2439:0314/092254.954394:43006117:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [2439:2439:0314/092254.954630:43006354:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2439:2439:0314/092254.954728:43006452:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 1672 with a delay 0, Now = 211419424 [2439:2439:0314/092254.954799:43006523:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000af0 with delay 0 [2439:2439:0314/092254.954916:43006640: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 [2439:2439:0314/092254.954998:43006723:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000af0 [2439:2439:0314/092254.955131:43006854:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000b10 with delay 0 [2439:2439:0314/092254.955211:43006934:INFO:recurring-task.cc(55)] [Retry] Scheduling 1672 with a delay 10000000, Now = 211419424 [2439:2439:0314/092254.955290:43007014:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x7b0400000c90 with delay 10000 [2439:2439:0314/092254.955376:43007097:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x7b0400000b10 [2439:2439:0314/092254.955440:43007163:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [2439:2439:0314/092254.955641:43007368:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x7b0400000c90 [2439:2439:0314/092254.956244:43007966:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x7b0400000ac0 [2439:2439:0314/092254.969131:43020855:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x7b0400000a50 [2439:2439:0314/092254.969256:43020980:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2439:2439:0314/092254.969372:43021095:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [2439:2439:0314/092254.969447:43021171:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [2439:2439:0314/092254.969846:43021573: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 } [2439:2439:0314/092254.969940:43021663:INFO:recurring-task.cc(55)] [Send-info] Scheduling 8456 with a delay 500000, Now = 1411419424 [2439:2439:0314/092254.970012:43021736:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7b0400000ac0 with delay 500 [2439:2439:0314/092254.970096:43021820:INFO:recurring-task.cc(55)] [Retry] Scheduling 1688 with a delay 1200000000, Now = 1411419424 [2439:2439:0314/092254.970174:43021898:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x7b0400000c90 with delay 1200000 [2439:2439:0314/092254.970255:43021977:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x7b0400000ac0 [2439:2439:0314/092254.970326:43022049:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.970435:43022158:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [2439:2439:0314/092254.970508:43022232:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [2439:2439:0314/092254.971051:43022775: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 (22 ms) [28/28] InvalidationClientImplTest.Heartbeats (22 ms) SUCCESS: all tests passed. Tests took 0 seconds. 2019-03-14 10:16:30,147 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmpANdRtW/4396007c0ca9ce10'] 2019-03-14 10:16:30,148 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmpANdRtW/4396007c0ca9ce10/output.json'] 2019-03-14 10:16:30,148 - root: [INFO] merge_cmd: /b/swarming/w/ir/cache/vpython/ba947a/bin/python /b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py --build-properties {"bot_id": "swarm323-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "user:luci-scheduler@appspot.gserviceaccount.com", "created_ts": 1552583359521792, "id": "8918992067164676304", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux TSan Tests/35497", "builder:Linux TSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "gitiles_ref:refs/heads/master", "parent_buildername:Linux TSan Builder", "parent_buildnumber:42725", "scheduler_invocation_id:9084422129189990416", "scheduler_job_id:chromium/Linux TSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux TSan Tests", "buildnumber": 35497, "got_angle_revision": "094c40dce6015add9e9524364a4e9b0523b7c31e", "got_dawn_revision": "ea2c7f20f2f96e15570f7e9416fb6c826f809747", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "got_revision_cp": "refs/heads/master@{#640796}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "a4404f08610f8dde2b745329ac5813c4a6a84c70", "got_v8_revision_cp": "refs/heads/7.5.38@{#1}", "got_webrtc_revision": "d841ea6b586a81065f78d3eae7ab82c505cda1d8", "got_webrtc_revision_cp": "refs/heads/master@{#27121}", "mastername": "chromium.memory", "parent_buildername": "Linux TSan Builder", "parent_got_angle_revision": "094c40dce6015add9e9524364a4e9b0523b7c31e", "parent_got_dawn_revision": "ea2c7f20f2f96e15570f7e9416fb6c826f809747", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "parent_got_revision_cp": "refs/heads/master@{#640796}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "a4404f08610f8dde2b745329ac5813c4a6a84c70", "parent_got_v8_revision_cp": "refs/heads/7.5.38@{#1}", "parent_got_webrtc_revision": "d841ea6b586a81065f78d3eae7ab82c505cda1d8", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27121}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "swarm_hashes": {"accessibility_unittests": "bd5e6db4b676fd014f55de6b34acb38814e4023e", "angle_unittests": "763013b4e1e6cdc25c633b4baf9c75bf9813d31d", "app_shell_unittests": "73c709a5168eb6dcc5eaa96a04867dcd015ebe02", "aura_unittests": "9966646d4921361777ad77e183761b3f8a07e14f", "base_unittests": "6b61b4ca9c6dfdab5c394b15f5c1fa4f9dcfacf7", "blink_common_unittests": "770987225d223ba70c446a2e3a1e10ed1257fc8e", "blink_fuzzer_unittests": "848509de7a997a9d9bd09bf01340e2259106ddd6", "blink_heap_unittests": "950ea8d2aa3f9688635bf57ea6922703a2a39a91", "blink_platform_unittests": "7548ee8138505558f830afca909aee02939a159f", "blink_unittests": "b52ea8255ceb02e01e6e630ab6e348191f0104cd", "boringssl_crypto_tests": "31383dd12bb3660af192869f1d660b5162147258", "boringssl_ssl_tests": "86cf06d1fc726982075785f5a3df40b415e14a4f", "browser_tests": "daf81ca849328c89b3b0679f4c07406b769ec737", "cacheinvalidation_unittests": "ef2168a186aaef68c64438486a235648f9bda843", "capture_unittests": "7751f7713228751b0b0b76ec905ce369e207a953", "cast_unittests": "e9b89adcd935e40a559b010471f939f0e86fea24", "cc_unittests": "668162daa3b5140e91059e2a076e15021edc67c7", "chrome_app_unittests": "fb5e0852ee27894a9107973d9aa3e80333939580", "chromedriver_unittests": "d0944dc48261781dbd121016fb7d726379a7ac6c", "components_browsertests": "bf9a0a2f78d92969c1b9bfc8c93db39f0b05bbda", "components_unittests": "38ad8d50e0ba8d00a151157e2a5d48f4417dd2be", "compositor_unittests": "ccb73ae8ed014bc9c42a76b8c03c3f04ae97dab1", "content_browsertests": "e7dc36a62b86e573733d3bf046c1adef9bfb91df", "content_unittests": "5c5b73aa5b00bdefe6462852dbef1fec3680648a", "cronet_tests": "f13f11ae3f6798ced9f62384bc49293707d35a08", "cronet_unittests": "266b1a9e4b21aebbc20315925f07bb4dacec080c", "crypto_unittests": "a3fbc979f2894c146fe361e9d0cb4be21441d1c2", "dbus_unittests": "117b2a60cb55d8f25f0ed393e361e595fd2857ba", "device_unittests": "a92e33d257709c54dee6678cd1f08a12b9438843", "display_unittests": "47d228897c6ab66e59f007797df4ffbda9af4abf", "events_unittests": "fc10681c10d993dce7219c5f2dd9a8760dd18610", "extensions_browsertests": "e176916ac6aa6c574c781a3b07bc9b9dbac460c0", "extensions_unittests": "797e258b6a8cffb3af29f5c18d822282c1586cab", "filesystem_service_unittests": "ba4e555ccdea82e74fa902ec804dae749e480f71", "gcm_unit_tests": "b65d823adeeca128a04bddd2bd2c49d782bb33c2", "gfx_unittests": "432fa939836128a9084aea053edaec59487a2bbe", "gin_unittests": "f0207bc128b4d4c0e0808f5ce300a580c682fd26", "gl_tests": "a8b7bc256d2cf7df81af028cc61ba60c87669e1c", "gl_unittests": "f3c6fda5e9a97f7d8ac0fcfcd9d2ef9fd441afa4", "google_apis_unittests": "7ba3fea8df71315f56a56b177cdc01158b09f04c", "gpu_unittests": "c7cb99cb3abb6b3eda007580ec184e564486d3fe", "headless_browsertests": "12e45c752dd9f778135a4bdfb57dc9f80b1a916f", "headless_unittests": "2818679ba67e08abe7e144180f7d678d28d9c7c1", "interactive_ui_tests": "5d12c3829e03421a53a90d010fa3b65be9565bf1", "ipc_tests": "efebeb50369a9c366d122983222eb032bd297d41", "jingle_unittests": "61e0cde960bd3d589778fe712636cefea4410b62", "latency_unittests": "740b1607db423ae552b6e3b51fb3bcfdec5eff48", "leveldb_service_unittests": "b012937976b230e898b7f97581e6dd8171849450", "libjingle_xmpp_unittests": "9e0cecaa9cb3c2ebbbfa7a40a334642b253bdee5", "media_blink_unittests": "6c800250e2649db391d93011d97dfb15aef4fcd2", "media_service_unittests": "5d61b49da07ca4d90d1c52de78735b809d685776", "media_unittests": "39f650d98f882d1e559214be6c3271fe97903668", "message_center_unittests": "58a1d2bd3cc0cf2831ac42789caeb6b6cd8ed9b9", "midi_unittests": "bb3c8312a59acaf25261e559978a6b14119e7cad", "mojo_core_unittests": "51bb216786158f43a5372bf71f220b45b78b00d2", "mojo_unittests": "332a327db1fbb5b10ffd36ab08d58053c954721b", "native_theme_unittests": "e88ff2f86c605ccd643af402a59df8027fbeefc5", "net_unittests": "f9219e6dcb1075d48015dcac1fd32dc70fdf967f", "pdf_unittests": "97d1cd2192aca19fabeb8118501996106b29c8a7", "ppapi_unittests": "1e409fd253b204a8a5305e266e68f67e0545f889", "printing_unittests": "361867963a06f2b6c7ac58e9f96f5ecead87ed87", "remoting_unittests": "d10b3257802f2235612f74cb6324ececa4f3bbc5", "sandbox_linux_unittests": "ad25386e7203628df7eac034c6e02e5514402582", "service_manager_unittests": "a67bf71132c7ac48e9f06865228980b64ae87f75", "services_unittests": "4fb66585b8b509415c56d1d493e913dc26865ba0", "shell_dialogs_unittests": "5ce654ddfe0031d9bc1627e108450ed17735e805", "skia_unittests": "c61a0726e2cafd000c577ce594cccc003311d3b4", "snapshot_unittests": "67dc7662cfe22d0163b9b12f6032bfeea437ac9a", "sql_unittests": "ab0b7c9a9458da975427b599665a2e36f077ead7", "storage_unittests": "b979bf5e0902aa2e47d8d6380c146038af2ca42d", "sync_integration_tests": "2dd07ab05e0a0082a8e224f7e50018180b8cb07a", "traffic_annotation_auditor_unittests": "418dcebad9a7a94cab8eba04dfff8dd03ad3407d", "ui_base_unittests": "689a5de29342598ccba2f34620d87c457d5cabe6", "ui_touch_selection_unittests": "aebef3735b434e20bf6a2f8f081e3df22cd56ee7", "unit_tests": "5aaca57f171465ebd6c9ef9c574ad248434ff23e", "url_unittests": "025e3dfdb9f142c6161fc0f9541b66752233e28c", "views_unittests": "4d9ba61910328eb5759c6af795888eda1eaac7fe", "viz_unittests": "104704e9e5b1dab1fba809b9e79c87255583219b", "vr_common_unittests": "b8a8c31335ce510a574e039eac392c299d0b70fd", "vr_pixeltests": "8209a6668387366fa6a1a4077a1eff0b1cb3d9d2", "wm_unittests": "e41e6ae46787272c70f332826821981414d6880b", "wtf_unittests": "4290e041f8ca577eb42f95a6e47dbcaabcbc23a1"}} --summary-json /b/swarming/w/ir/tmp/t/tmp5r6Zoc.json --task-output-dir /b/swarming/w/ir/tmp/t/tmpANdRtW -o /b/swarming/w/ir/tmp/t/tmpcjeF9o.json /b/swarming/w/ir/tmp/t/tmpANdRtW/4396007c0ca9ce10/output.json Running ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "swarm323-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "user:luci-scheduler@appspot.gserviceaccount.com", "created_ts": 1552583359521792, "id": "8918992067164676304", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux TSan Tests/35497", "builder:Linux TSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "gitiles_ref:refs/heads/master", "parent_buildername:Linux TSan Builder", "parent_buildnumber:42725", "scheduler_invocation_id:9084422129189990416", "scheduler_job_id:chromium/Linux TSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux TSan Tests", "buildnumber": 35497, "got_angle_revision": "094c40dce6015add9e9524364a4e9b0523b7c31e", "got_dawn_revision": "ea2c7f20f2f96e15570f7e9416fb6c826f809747", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "got_revision_cp": "refs/heads/master@{#640796}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "a4404f08610f8dde2b745329ac5813c4a6a84c70", "got_v8_revision_cp": "refs/heads/7.5.38@{#1}", "got_webrtc_revision": "d841ea6b586a81065f78d3eae7ab82c505cda1d8", "got_webrtc_revision_cp": "refs/heads/master@{#27121}", "mastername": "chromium.memory", "parent_buildername": "Linux TSan Builder", "parent_got_angle_revision": "094c40dce6015add9e9524364a4e9b0523b7c31e", "parent_got_dawn_revision": "ea2c7f20f2f96e15570f7e9416fb6c826f809747", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "parent_got_revision_cp": "refs/heads/master@{#640796}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "a4404f08610f8dde2b745329ac5813c4a6a84c70", "parent_got_v8_revision_cp": "refs/heads/7.5.38@{#1}", "parent_got_webrtc_revision": "d841ea6b586a81065f78d3eae7ab82c505cda1d8", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27121}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "swarm_hashes": {"accessibility_unittests": "bd5e6db4b676fd014f55de6b34acb38814e4023e", "angle_unittests": "763013b4e1e6cdc25c633b4baf9c75bf9813d31d", "app_shell_unittests": "73c709a5168eb6dcc5eaa96a04867dcd015ebe02", "aura_unittests": "9966646d4921361777ad77e183761b3f8a07e14f", "base_unittests": "6b61b4ca9c6dfdab5c394b15f5c1fa4f9dcfacf7", "blink_common_unittests": "770987225d223ba70c446a2e3a1e10ed1257fc8e", "blink_fuzzer_unittests": "848509de7a997a9d9bd09bf01340e2259106ddd6", "blink_heap_unittests": "950ea8d2aa3f9688635bf57ea6922703a2a39a91", "blink_platform_unittests": "7548ee8138505558f830afca909aee02939a159f", "blink_unittests": "b52ea8255ceb02e01e6e630ab6e348191f0104cd", "boringssl_crypto_tests": "31383dd12bb3660af192869f1d660b5162147258", "boringssl_ssl_tests": "86cf06d1fc726982075785f5a3df40b415e14a4f", "browser_tests": "daf81ca849328c89b3b0679f4c07406b769ec737", "cacheinvalidation_unittests": "ef2168a186aaef68c64438486a235648f9bda843", "capture_unittests": "7751f7713228751b0b0b76ec905ce369e207a953", "cast_unittests": "e9b89adcd935e40a559b010471f939f0e86fea24", "cc_unittests": "668162daa3b5140e91059e2a076e15021edc67c7", "chrome_app_unittests": "fb5e0852ee27894a9107973d9aa3e80333939580", "chromedriver_unittests": "d0944dc48261781dbd121016fb7d726379a7ac6c", "components_browsertests": "bf9a0a2f78d92969c1b9bfc8c93db39f0b05bbda", "components_unittests": "38ad8d50e0ba8d00a151157e2a5d48f4417dd2be", "compositor_unittests": "ccb73ae8ed014bc9c42a76b8c03c3f04ae97dab1", "content_browsertests": "e7dc36a62b86e573733d3bf046c1adef9bfb91df", "content_unittests": "5c5b73aa5b00bdefe6462852dbef1fec3680648a", "cronet_tests": "f13f11ae3f6798ced9f62384bc49293707d35a08", "cronet_unittests": "266b1a9e4b21aebbc20315925f07bb4dacec080c", "crypto_unittests": "a3fbc979f2894c146fe361e9d0cb4be21441d1c2", "dbus_unittests": "117b2a60cb55d8f25f0ed393e361e595fd2857ba", "device_unittests": "a92e33d257709c54dee6678cd1f08a12b9438843", "display_unittests": "47d228897c6ab66e59f007797df4ffbda9af4abf", "events_unittests": "fc10681c10d993dce7219c5f2dd9a8760dd18610", "extensions_browsertests": "e176916ac6aa6c574c781a3b07bc9b9dbac460c0", "extensions_unittests": "797e258b6a8cffb3af29f5c18d822282c1586cab", "filesystem_service_unittests": "ba4e555ccdea82e74fa902ec804dae749e480f71", "gcm_unit_tests": "b65d823adeeca128a04bddd2bd2c49d782bb33c2", "gfx_unittests": "432fa939836128a9084aea053edaec59487a2bbe", "gin_unittests": "f0207bc128b4d4c0e0808f5ce300a580c682fd26", "gl_tests": "a8b7bc256d2cf7df81af028cc61ba60c87669e1c", "gl_unittests": "f3c6fda5e9a97f7d8ac0fcfcd9d2ef9fd441afa4", "google_apis_unittests": "7ba3fea8df71315f56a56b177cdc01158b09f04c", "gpu_unittests": "c7cb99cb3abb6b3eda007580ec184e564486d3fe", "headless_browsertests": "12e45c752dd9f778135a4bdfb57dc9f80b1a916f", "headless_unittests": "2818679ba67e08abe7e144180f7d678d28d9c7c1", "interactive_ui_tests": "5d12c3829e03421a53a90d010fa3b65be9565bf1", "ipc_tests": "efebeb50369a9c366d122983222eb032bd297d41", "jingle_unittests": "61e0cde960bd3d589778fe712636cefea4410b62", "latency_unittests": "740b1607db423ae552b6e3b51fb3bcfdec5eff48", "leveldb_service_unittests": "b012937976b230e898b7f97581e6dd8171849450", "libjingle_xmpp_unittests": "9e0cecaa9cb3c2ebbbfa7a40a334642b253bdee5", "media_blink_unittests": "6c800250e2649db391d93011d97dfb15aef4fcd2", "media_service_unittests": "5d61b49da07ca4d90d1c52de78735b809d685776", "media_unittests": "39f650d98f882d1e559214be6c3271fe97903668", "message_center_unittests": "58a1d2bd3cc0cf2831ac42789caeb6b6cd8ed9b9", "midi_unittests": "bb3c8312a59acaf25261e559978a6b14119e7cad", "mojo_core_unittests": "51bb216786158f43a5372bf71f220b45b78b00d2", "mojo_unittests": "332a327db1fbb5b10ffd36ab08d58053c954721b", "native_theme_unittests": "e88ff2f86c605ccd643af402a59df8027fbeefc5", "net_unittests": "f9219e6dcb1075d48015dcac1fd32dc70fdf967f", "pdf_unittests": "97d1cd2192aca19fabeb8118501996106b29c8a7", "ppapi_unittests": "1e409fd253b204a8a5305e266e68f67e0545f889", "printing_unittests": "361867963a06f2b6c7ac58e9f96f5ecead87ed87", "remoting_unittests": "d10b3257802f2235612f74cb6324ececa4f3bbc5", "sandbox_linux_unittests": "ad25386e7203628df7eac034c6e02e5514402582", "service_manager_unittests": "a67bf71132c7ac48e9f06865228980b64ae87f75", "services_unittests": "4fb66585b8b509415c56d1d493e913dc26865ba0", "shell_dialogs_unittests": "5ce654ddfe0031d9bc1627e108450ed17735e805", "skia_unittests": "c61a0726e2cafd000c577ce594cccc003311d3b4", "snapshot_unittests": "67dc7662cfe22d0163b9b12f6032bfeea437ac9a", "sql_unittests": "ab0b7c9a9458da975427b599665a2e36f077ead7", "storage_unittests": "b979bf5e0902aa2e47d8d6380c146038af2ca42d", "sync_integration_tests": "2dd07ab05e0a0082a8e224f7e50018180b8cb07a", "traffic_annotation_auditor_unittests": "418dcebad9a7a94cab8eba04dfff8dd03ad3407d", "ui_base_unittests": "689a5de29342598ccba2f34620d87c457d5cabe6", "ui_touch_selection_unittests": "aebef3735b434e20bf6a2f8f081e3df22cd56ee7", "unit_tests": "5aaca57f171465ebd6c9ef9c574ad248434ff23e", "url_unittests": "025e3dfdb9f142c6161fc0f9541b66752233e28c", "views_unittests": "4d9ba61910328eb5759c6af795888eda1eaac7fe", "viz_unittests": "104704e9e5b1dab1fba809b9e79c87255583219b", "vr_common_unittests": "b8a8c31335ce510a574e039eac392c299d0b70fd", "vr_pixeltests": "8209a6668387366fa6a1a4077a1eff0b1cb3d9d2", "wm_unittests": "e41e6ae46787272c70f332826821981414d6880b", "wtf_unittests": "4290e041f8ca577eb42f95a6e47dbcaabcbc23a1"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp5r6Zoc.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpANdRtW', '-o', '/b/swarming/w/ir/tmp/t/tmpcjeF9o.json', '/b/swarming/w/ir/tmp/t/tmpANdRtW/4396007c0ca9ce10/output.json'] in None (env: None) Command ['/b/swarming/w/ir/cache/vpython/ba947a/bin/python', '/b/swarming/w/ir/cache/builder/src/testing/merge_scripts/standard_gtest_merge.py', '--build-properties', '{"bot_id": "swarm323-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "user:luci-scheduler@appspot.gserviceaccount.com", "created_ts": 1552583359521792, "id": "8918992067164676304", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux TSan Tests/35497", "builder:Linux TSan Tests", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "gitiles_ref:refs/heads/master", "parent_buildername:Linux TSan Builder", "parent_buildnumber:42725", "scheduler_invocation_id:9084422129189990416", "scheduler_job_id:chromium/Linux TSan Tests", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux TSan Tests", "buildnumber": 35497, "got_angle_revision": "094c40dce6015add9e9524364a4e9b0523b7c31e", "got_dawn_revision": "ea2c7f20f2f96e15570f7e9416fb6c826f809747", "got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "got_revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "got_revision_cp": "refs/heads/master@{#640796}", "got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "got_v8_revision": "a4404f08610f8dde2b745329ac5813c4a6a84c70", "got_v8_revision_cp": "refs/heads/7.5.38@{#1}", "got_webrtc_revision": "d841ea6b586a81065f78d3eae7ab82c505cda1d8", "got_webrtc_revision_cp": "refs/heads/master@{#27121}", "mastername": "chromium.memory", "parent_buildername": "Linux TSan Builder", "parent_got_angle_revision": "094c40dce6015add9e9524364a4e9b0523b7c31e", "parent_got_dawn_revision": "ea2c7f20f2f96e15570f7e9416fb6c826f809747", "parent_got_nacl_revision": "1ed9878b8eb68c1e0d0268754dafcf83e747fa8f", "parent_got_revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "parent_got_revision_cp": "refs/heads/master@{#640796}", "parent_got_swarming_client_revision": "7a61cf37d6a0163f0ec02d495289a1d038e62457", "parent_got_v8_revision": "a4404f08610f8dde2b745329ac5813c4a6a84c70", "parent_got_v8_revision_cp": "refs/heads/7.5.38@{#1}", "parent_got_webrtc_revision": "d841ea6b586a81065f78d3eae7ab82c505cda1d8", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27121}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "4d3ed7be37596bab2c1a98ddc5649924d98aecf8", "swarm_hashes": {"accessibility_unittests": "bd5e6db4b676fd014f55de6b34acb38814e4023e", "angle_unittests": "763013b4e1e6cdc25c633b4baf9c75bf9813d31d", "app_shell_unittests": "73c709a5168eb6dcc5eaa96a04867dcd015ebe02", "aura_unittests": "9966646d4921361777ad77e183761b3f8a07e14f", "base_unittests": "6b61b4ca9c6dfdab5c394b15f5c1fa4f9dcfacf7", "blink_common_unittests": "770987225d223ba70c446a2e3a1e10ed1257fc8e", "blink_fuzzer_unittests": "848509de7a997a9d9bd09bf01340e2259106ddd6", "blink_heap_unittests": "950ea8d2aa3f9688635bf57ea6922703a2a39a91", "blink_platform_unittests": "7548ee8138505558f830afca909aee02939a159f", "blink_unittests": "b52ea8255ceb02e01e6e630ab6e348191f0104cd", "boringssl_crypto_tests": "31383dd12bb3660af192869f1d660b5162147258", "boringssl_ssl_tests": "86cf06d1fc726982075785f5a3df40b415e14a4f", "browser_tests": "daf81ca849328c89b3b0679f4c07406b769ec737", "cacheinvalidation_unittests": "ef2168a186aaef68c64438486a235648f9bda843", "capture_unittests": "7751f7713228751b0b0b76ec905ce369e207a953", "cast_unittests": "e9b89adcd935e40a559b010471f939f0e86fea24", "cc_unittests": "668162daa3b5140e91059e2a076e15021edc67c7", "chrome_app_unittests": "fb5e0852ee27894a9107973d9aa3e80333939580", "chromedriver_unittests": "d0944dc48261781dbd121016fb7d726379a7ac6c", "components_browsertests": "bf9a0a2f78d92969c1b9bfc8c93db39f0b05bbda", "components_unittests": "38ad8d50e0ba8d00a151157e2a5d48f4417dd2be", "compositor_unittests": "ccb73ae8ed014bc9c42a76b8c03c3f04ae97dab1", "content_browsertests": "e7dc36a62b86e573733d3bf046c1adef9bfb91df", "content_unittests": "5c5b73aa5b00bdefe6462852dbef1fec3680648a", "cronet_tests": "f13f11ae3f6798ced9f62384bc49293707d35a08", "cronet_unittests": "266b1a9e4b21aebbc20315925f07bb4dacec080c", "crypto_unittests": "a3fbc979f2894c146fe361e9d0cb4be21441d1c2", "dbus_unittests": "117b2a60cb55d8f25f0ed393e361e595fd2857ba", "device_unittests": "a92e33d257709c54dee6678cd1f08a12b9438843", "display_unittests": "47d228897c6ab66e59f007797df4ffbda9af4abf", "events_unittests": "fc10681c10d993dce7219c5f2dd9a8760dd18610", "extensions_browsertests": "e176916ac6aa6c574c781a3b07bc9b9dbac460c0", "extensions_unittests": "797e258b6a8cffb3af29f5c18d822282c1586cab", "filesystem_service_unittests": "ba4e555ccdea82e74fa902ec804dae749e480f71", "gcm_unit_tests": "b65d823adeeca128a04bddd2bd2c49d782bb33c2", "gfx_unittests": "432fa939836128a9084aea053edaec59487a2bbe", "gin_unittests": "f0207bc128b4d4c0e0808f5ce300a580c682fd26", "gl_tests": "a8b7bc256d2cf7df81af028cc61ba60c87669e1c", "gl_unittests": "f3c6fda5e9a97f7d8ac0fcfcd9d2ef9fd441afa4", "google_apis_unittests": "7ba3fea8df71315f56a56b177cdc01158b09f04c", "gpu_unittests": "c7cb99cb3abb6b3eda007580ec184e564486d3fe", "headless_browsertests": "12e45c752dd9f778135a4bdfb57dc9f80b1a916f", "headless_unittests": "2818679ba67e08abe7e144180f7d678d28d9c7c1", "interactive_ui_tests": "5d12c3829e03421a53a90d010fa3b65be9565bf1", "ipc_tests": "efebeb50369a9c366d122983222eb032bd297d41", "jingle_unittests": "61e0cde960bd3d589778fe712636cefea4410b62", "latency_unittests": "740b1607db423ae552b6e3b51fb3bcfdec5eff48", "leveldb_service_unittests": "b012937976b230e898b7f97581e6dd8171849450", "libjingle_xmpp_unittests": "9e0cecaa9cb3c2ebbbfa7a40a334642b253bdee5", "media_blink_unittests": "6c800250e2649db391d93011d97dfb15aef4fcd2", "media_service_unittests": "5d61b49da07ca4d90d1c52de78735b809d685776", "media_unittests": "39f650d98f882d1e559214be6c3271fe97903668", "message_center_unittests": "58a1d2bd3cc0cf2831ac42789caeb6b6cd8ed9b9", "midi_unittests": "bb3c8312a59acaf25261e559978a6b14119e7cad", "mojo_core_unittests": "51bb216786158f43a5372bf71f220b45b78b00d2", "mojo_unittests": "332a327db1fbb5b10ffd36ab08d58053c954721b", "native_theme_unittests": "e88ff2f86c605ccd643af402a59df8027fbeefc5", "net_unittests": "f9219e6dcb1075d48015dcac1fd32dc70fdf967f", "pdf_unittests": "97d1cd2192aca19fabeb8118501996106b29c8a7", "ppapi_unittests": "1e409fd253b204a8a5305e266e68f67e0545f889", "printing_unittests": "361867963a06f2b6c7ac58e9f96f5ecead87ed87", "remoting_unittests": "d10b3257802f2235612f74cb6324ececa4f3bbc5", "sandbox_linux_unittests": "ad25386e7203628df7eac034c6e02e5514402582", "service_manager_unittests": "a67bf71132c7ac48e9f06865228980b64ae87f75", "services_unittests": "4fb66585b8b509415c56d1d493e913dc26865ba0", "shell_dialogs_unittests": "5ce654ddfe0031d9bc1627e108450ed17735e805", "skia_unittests": "c61a0726e2cafd000c577ce594cccc003311d3b4", "snapshot_unittests": "67dc7662cfe22d0163b9b12f6032bfeea437ac9a", "sql_unittests": "ab0b7c9a9458da975427b599665a2e36f077ead7", "storage_unittests": "b979bf5e0902aa2e47d8d6380c146038af2ca42d", "sync_integration_tests": "2dd07ab05e0a0082a8e224f7e50018180b8cb07a", "traffic_annotation_auditor_unittests": "418dcebad9a7a94cab8eba04dfff8dd03ad3407d", "ui_base_unittests": "689a5de29342598ccba2f34620d87c457d5cabe6", "ui_touch_selection_unittests": "aebef3735b434e20bf6a2f8f081e3df22cd56ee7", "unit_tests": "5aaca57f171465ebd6c9ef9c574ad248434ff23e", "url_unittests": "025e3dfdb9f142c6161fc0f9541b66752233e28c", "views_unittests": "4d9ba61910328eb5759c6af795888eda1eaac7fe", "viz_unittests": "104704e9e5b1dab1fba809b9e79c87255583219b", "vr_common_unittests": "b8a8c31335ce510a574e039eac392c299d0b70fd", "vr_pixeltests": "8209a6668387366fa6a1a4077a1eff0b1cb3d9d2", "wm_unittests": "e41e6ae46787272c70f332826821981414d6880b", "wtf_unittests": "4290e041f8ca577eb42f95a6e47dbcaabcbc23a1"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmp5r6Zoc.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmpANdRtW', '-o', '/b/swarming/w/ir/tmp/t/tmpcjeF9o.json', '/b/swarming/w/ir/tmp/t/tmpANdRtW/4396007c0ca9ce10/output.json'] returned exit code 0