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/tmpjTzCCj.json --task-output-dir /b/swarming/w/ir/tmp/t/tmplF3XKE --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/tmpZwNy8Gmerge_script_log --merge-additional-args '[]' --build-properties '{"bot_id": "swarm2376-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1555919321790524, "id": "8915494057192899376", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux Chromium OS ASan LSan Tests (1)/32916", "builder:Linux Chromium OS ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/a6043f15f391be302c9b104d94359d54723c6d8d", "gitiles_ref:refs/heads/master", "parent_buildername:Linux Chromium OS ASan LSan Builder", "parent_buildnumber:44879", "scheduler_invocation_id:9080924119187250528", "scheduler_job_id:chromium/Linux Chromium OS ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux Chromium OS ASan LSan Tests (1)", "buildnumber": 32916, "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "got_revision_cp": "refs/heads/master@{#652813}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "chromium.memory", "parent_buildername": "Linux Chromium OS ASan LSan Builder", "parent_got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "parent_got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "parent_got_revision_cp": "refs/heads/master@{#652813}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "parent_got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "parent_got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27678}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "swarm_hashes": {"accessibility_unittests": "30691e08012156d9b1a4a61f92d6d9d7042c0530", "angle_unittests": "3468e8e17d7f4791b7848ff61a58de441a312ab8", "app_list_unittests": "10718f7035bb6b73f244bf0b2d257e9e4a078b06", "app_shell_unittests": "523dc712fe3918680886c4cbeba6ae788535a39f", "ash_unittests": "e6ef7875fb4b50c62d357f2243f97f20d4e85ed5", "aura_unittests": "84dd8b42ab683bfc38d1ece7f1810c8a25592e36", "base_unittests": "a32478c89417e8045dde4f6902bb5b54083a7ec1", "blink_common_unittests": "a6eadda574f2f72d9bc771634cddbfe9fd1b9400", "blink_fuzzer_unittests": "e88db7944eec25713d967eb94f51daea7fdae2f0", "blink_heap_unittests": "454088795a253b039f34e348fc9a97521214c998", "blink_platform_unittests": "5322b95e243fe267b6e7c9421c37aac746fdd9af", "blink_unittests": "795ddfa50b66a6d218a56cac88e28f0302f37cde", "boringssl_crypto_tests": "c2f334da5178ba2ca3904540296c350482cf81d0", "boringssl_ssl_tests": "1272e9547f075b3f49631b2c5f8461fcd92fcc7a", "browser_tests": "6a6c66f7add80c520d7bb070016769220c2b78c6", "cacheinvalidation_unittests": "c2867b5786c4d50cf798088a562927240780f261", "capture_unittests": "aaca36a72085818fcbe3ebe0679da956629c3322", "cast_unittests": "66a0beebe1f96157e6d60397fc8c653e9ca3be7c", "cc_unittests": "a9d2debdce4f1c7b74fd1f468b68878a45758616", "chrome_app_unittests": "23f30377a2e93f7a34bc48f922774fe27e8ed62d", "chromedriver_unittests": "cebbd7e8aa576165555a541ba9a3b13b9ceb69d7", "chromeos_components_unittests": "178e3b882fd8f2a613e3a54334f5edd9cef1e460", "chromeos_unittests": "f2d23cc501c84553da82f66b0520c1e6e87ead53", "components_browsertests": "da6444e3f33f8f45534e6a61c5f11dad75ecc857", "components_unittests": "7509985a5dce24f0d0e00061f0fd4c17a5b836af", "compositor_unittests": "979c2a5deb3d75186443823aab31a5df38efb356", "content_browsertests": "fe13b470ff7f61d88321be3d1352d4c5bc593ed8", "content_unittests": "b27eed502e07c9003cc28611cbd4ab41a9a6283f", "crypto_unittests": "7f61e87da65c17ca8ad64c030b77f531c3efa9e9", "dbus_unittests": "c92afac4c7ee545556fc9633efc8bf57fcad4c0f", "device_unittests": "637142f5ecbeec7288373708f7c96c433062bff0", "display_unittests": "fa93a48ab72352eb316272e8cd174d2ab5daea7b", "events_unittests": "3fb3632f4f1e97993548ed398a213d93066eff89", "exo_unittests": "b7588c9bd7bc85ac7e3b62f04ddd8014c299846c", "extensions_browsertests": "c6b1be7127b5523d2e3a846b0093fad694955bd9", "extensions_unittests": "85f05c3682b5cbd499cd2c43053f3738ab305fde", "filesystem_service_unittests": "388d408d7357ee4166a1a8bd7480caccfda0e63f", "gcm_unit_tests": "94a80d7fb19feb2cbff0dac3213f287869a6830c", "gfx_unittests": "d8b1d49cb6018e4dea0b3020e54b734e737b8a1b", "gl_unittests_ozone": "087c2b16bd05e1c45eaffbfbb0063919ed0aa76c", "google_apis_unittests": "dbd965bd8a1a1c582ff3bbc165aaa5eaa12cb838", "gpu_unittests": "bdbb72f43db921b4a9703d31d85472f573f6f758", "interactive_ui_tests": "cf7f5c9d2c2385e346986262f23cb063c2e7ffd3", "ipc_tests": "2d462d862a879c18e72311eba43bafeb6a5aac60", "jingle_unittests": "93a4aabbaa184c2ab67030f6b65d3d41730c39ff", "keyboard_unittests": "7a8a3a6a7156261a3dbea0bdade9492d86c37334", "latency_unittests": "6c38a2ea796bb761a98c108917e7d2f03e364af7", "leveldb_service_unittests": "49412188bc723d8fec4bd49bca4b150b6327250b", "libjingle_xmpp_unittests": "191c536f10d4a088bea5cfe5ec8b8d4780b8f9ae", "media_blink_unittests": "8cfb49d6085fadfa0d752b37faf4c8b78f0fb0b1", "media_service_unittests": "789fbb2cfcd4f6d68ba40474a48c5828b3e58ad4", "media_unittests": "61aea81b826c21c4418e6831fd35c05aceb43a1a", "message_center_unittests": "e2369ca8656dc3495353ad5f6c8883d1fc52114b", "midi_unittests": "3ac38c78dbc5cce75d2753f2169a0b16699ac1ac", "mojo_core_unittests": "23b1dd3c99a86e73f5a2d014aed64b71ea1f5159", "mojo_unittests": "9c62fba34390e76f027c408bf231884b7b3cfb54", "nacl_helper_nonsfi_unittests": "03d6a9a9906d64afa55b7427a602b35dd43034c2", "nacl_loader_unittests": "7112b0bff15b2d4a57867a9310f96d5975d87ebb", "native_theme_unittests": "e51973dba9a60dd016baa0caa84853a1d8141aa9", "net_unittests": "b3a5aab1d5d2b7f68bfce33989c6c55c4ab6583b", "ozone_gl_unittests": "6cce07f7d3a2687770f46aed7dc257d9c84fc3d8", "ozone_unittests": "8fe310399f4d3d4e3aea4e475cda7c4ec90bf53d", "ozone_x11_unittests": "1de4ce9a0eda735d0b8ee87b4cfa451fea47df67", "pdf_unittests": "c7d89d8b63918b0821bfbaa4a7bc95a9e95e68a2", "perfetto_unittests": "ecc4f566d8ae270faec55c02913de14eb319249e", "ppapi_unittests": "04aea971086845ae07592c05cb8515e7a19e076c", "printing_unittests": "1dfbec3b3d4dfdc617d2c39426fbb1dfe9dc46d0", "remoting_unittests": "1aa0f16f5303276102a00db5dc93f6e9e8f722ba", "sandbox_linux_unittests": "3582bbcd401d61ae91eea0053187785aece4822f", "service_manager_unittests": "c53df1939451cc9756ad35771b8c0b1f8ce49573", "services_unittests": "a21571a6d0f9904fd2444cb5617e58a85f1d3aa1", "shell_dialogs_unittests": "5b5fa37dad02a0d85c1c721fbaee986ce3444146", "skia_unittests": "e531702a972bdb4caaab0e20be57008da1067286", "snapshot_unittests": "b7a2d9bdffd18e54ff415c41a3da760774cfeacd", "sql_unittests": "a3d87c57d727cf9632ef610c3b86a201e48a0299", "storage_unittests": "fab5ff952e2bac33bfd4d3523bc6f547203025d1", "sync_integration_tests": "0385b60a931ed8734024d5ea029d794385524667", "traffic_annotation_auditor_unittests": "c67d9fe11e5a566302bca9a12130e4c741c8d284", "ui_base_unittests": "7873d9abebc42853e122035d4cc040a6a73ea644", "ui_chromeos_unittests": "f8ed2198ecdf741bc71dab6d71ac413df304a73f", "ui_touch_selection_unittests": "59e67da78e3fcc3ccce02e26d2c8e1b359635655", "unit_tests": "2874a7bbbd2f9889e64df2b1de973d54668479c1", "url_unittests": "fbb72e9f6309a097aeee9673be870833f6a44dab", "usage_time_limit_unittests": "f13edfc7eb9d5fb6f423a6e832f8f39cdc61d1f3", "views_unittests": "57dc91f1b782e443b5f060832ff12151a571c421", "viz_unittests": "2c4a581d32da18c0a23cfffd3def28604d6fadce", "wayland_client_perftests": "48e5b8c88f6816cef63f35c93f1ba015ce9776db", "wm_unittests": "0b26de8b3f70a0fbe117dd1e9a2f50d9e33f6c3e", "wtf_unittests": "682a8a015226b1fd4bf425e0db497d0aca797629"}}' --summary-json-file /b/swarming/w/ir/tmp/t/tmpKpgOAF.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/tmpnQOjML.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/tmpjTzCCj.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmplF3XKE', '--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/tmpZwNy8Gmerge_script_log', '--merge-additional-args', '[]', '--build-properties', '{"bot_id": "swarm2376-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1555919321790524, "id": "8915494057192899376", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux Chromium OS ASan LSan Tests (1)/32916", "builder:Linux Chromium OS ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/a6043f15f391be302c9b104d94359d54723c6d8d", "gitiles_ref:refs/heads/master", "parent_buildername:Linux Chromium OS ASan LSan Builder", "parent_buildnumber:44879", "scheduler_invocation_id:9080924119187250528", "scheduler_job_id:chromium/Linux Chromium OS ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux Chromium OS ASan LSan Tests (1)", "buildnumber": 32916, "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "got_revision_cp": "refs/heads/master@{#652813}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "chromium.memory", "parent_buildername": "Linux Chromium OS ASan LSan Builder", "parent_got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "parent_got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "parent_got_revision_cp": "refs/heads/master@{#652813}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "parent_got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "parent_got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27678}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "swarm_hashes": {"accessibility_unittests": "30691e08012156d9b1a4a61f92d6d9d7042c0530", "angle_unittests": "3468e8e17d7f4791b7848ff61a58de441a312ab8", "app_list_unittests": "10718f7035bb6b73f244bf0b2d257e9e4a078b06", "app_shell_unittests": "523dc712fe3918680886c4cbeba6ae788535a39f", "ash_unittests": "e6ef7875fb4b50c62d357f2243f97f20d4e85ed5", "aura_unittests": "84dd8b42ab683bfc38d1ece7f1810c8a25592e36", "base_unittests": "a32478c89417e8045dde4f6902bb5b54083a7ec1", "blink_common_unittests": "a6eadda574f2f72d9bc771634cddbfe9fd1b9400", "blink_fuzzer_unittests": "e88db7944eec25713d967eb94f51daea7fdae2f0", "blink_heap_unittests": "454088795a253b039f34e348fc9a97521214c998", "blink_platform_unittests": "5322b95e243fe267b6e7c9421c37aac746fdd9af", "blink_unittests": "795ddfa50b66a6d218a56cac88e28f0302f37cde", "boringssl_crypto_tests": "c2f334da5178ba2ca3904540296c350482cf81d0", "boringssl_ssl_tests": "1272e9547f075b3f49631b2c5f8461fcd92fcc7a", "browser_tests": "6a6c66f7add80c520d7bb070016769220c2b78c6", "cacheinvalidation_unittests": "c2867b5786c4d50cf798088a562927240780f261", "capture_unittests": "aaca36a72085818fcbe3ebe0679da956629c3322", "cast_unittests": "66a0beebe1f96157e6d60397fc8c653e9ca3be7c", "cc_unittests": "a9d2debdce4f1c7b74fd1f468b68878a45758616", "chrome_app_unittests": "23f30377a2e93f7a34bc48f922774fe27e8ed62d", "chromedriver_unittests": "cebbd7e8aa576165555a541ba9a3b13b9ceb69d7", "chromeos_components_unittests": "178e3b882fd8f2a613e3a54334f5edd9cef1e460", "chromeos_unittests": "f2d23cc501c84553da82f66b0520c1e6e87ead53", "components_browsertests": "da6444e3f33f8f45534e6a61c5f11dad75ecc857", "components_unittests": "7509985a5dce24f0d0e00061f0fd4c17a5b836af", "compositor_unittests": "979c2a5deb3d75186443823aab31a5df38efb356", "content_browsertests": "fe13b470ff7f61d88321be3d1352d4c5bc593ed8", "content_unittests": "b27eed502e07c9003cc28611cbd4ab41a9a6283f", "crypto_unittests": "7f61e87da65c17ca8ad64c030b77f531c3efa9e9", "dbus_unittests": "c92afac4c7ee545556fc9633efc8bf57fcad4c0f", "device_unittests": "637142f5ecbeec7288373708f7c96c433062bff0", "display_unittests": "fa93a48ab72352eb316272e8cd174d2ab5daea7b", "events_unittests": "3fb3632f4f1e97993548ed398a213d93066eff89", "exo_unittests": "b7588c9bd7bc85ac7e3b62f04ddd8014c299846c", "extensions_browsertests": "c6b1be7127b5523d2e3a846b0093fad694955bd9", "extensions_unittests": "85f05c3682b5cbd499cd2c43053f3738ab305fde", "filesystem_service_unittests": "388d408d7357ee4166a1a8bd7480caccfda0e63f", "gcm_unit_tests": "94a80d7fb19feb2cbff0dac3213f287869a6830c", "gfx_unittests": "d8b1d49cb6018e4dea0b3020e54b734e737b8a1b", "gl_unittests_ozone": "087c2b16bd05e1c45eaffbfbb0063919ed0aa76c", "google_apis_unittests": "dbd965bd8a1a1c582ff3bbc165aaa5eaa12cb838", "gpu_unittests": "bdbb72f43db921b4a9703d31d85472f573f6f758", "interactive_ui_tests": "cf7f5c9d2c2385e346986262f23cb063c2e7ffd3", "ipc_tests": "2d462d862a879c18e72311eba43bafeb6a5aac60", "jingle_unittests": "93a4aabbaa184c2ab67030f6b65d3d41730c39ff", "keyboard_unittests": "7a8a3a6a7156261a3dbea0bdade9492d86c37334", "latency_unittests": "6c38a2ea796bb761a98c108917e7d2f03e364af7", "leveldb_service_unittests": "49412188bc723d8fec4bd49bca4b150b6327250b", "libjingle_xmpp_unittests": "191c536f10d4a088bea5cfe5ec8b8d4780b8f9ae", "media_blink_unittests": "8cfb49d6085fadfa0d752b37faf4c8b78f0fb0b1", "media_service_unittests": "789fbb2cfcd4f6d68ba40474a48c5828b3e58ad4", "media_unittests": "61aea81b826c21c4418e6831fd35c05aceb43a1a", "message_center_unittests": "e2369ca8656dc3495353ad5f6c8883d1fc52114b", "midi_unittests": "3ac38c78dbc5cce75d2753f2169a0b16699ac1ac", "mojo_core_unittests": "23b1dd3c99a86e73f5a2d014aed64b71ea1f5159", "mojo_unittests": "9c62fba34390e76f027c408bf231884b7b3cfb54", "nacl_helper_nonsfi_unittests": "03d6a9a9906d64afa55b7427a602b35dd43034c2", "nacl_loader_unittests": "7112b0bff15b2d4a57867a9310f96d5975d87ebb", "native_theme_unittests": "e51973dba9a60dd016baa0caa84853a1d8141aa9", "net_unittests": "b3a5aab1d5d2b7f68bfce33989c6c55c4ab6583b", "ozone_gl_unittests": "6cce07f7d3a2687770f46aed7dc257d9c84fc3d8", "ozone_unittests": "8fe310399f4d3d4e3aea4e475cda7c4ec90bf53d", "ozone_x11_unittests": "1de4ce9a0eda735d0b8ee87b4cfa451fea47df67", "pdf_unittests": "c7d89d8b63918b0821bfbaa4a7bc95a9e95e68a2", "perfetto_unittests": "ecc4f566d8ae270faec55c02913de14eb319249e", "ppapi_unittests": "04aea971086845ae07592c05cb8515e7a19e076c", "printing_unittests": "1dfbec3b3d4dfdc617d2c39426fbb1dfe9dc46d0", "remoting_unittests": "1aa0f16f5303276102a00db5dc93f6e9e8f722ba", "sandbox_linux_unittests": "3582bbcd401d61ae91eea0053187785aece4822f", "service_manager_unittests": "c53df1939451cc9756ad35771b8c0b1f8ce49573", "services_unittests": "a21571a6d0f9904fd2444cb5617e58a85f1d3aa1", "shell_dialogs_unittests": "5b5fa37dad02a0d85c1c721fbaee986ce3444146", "skia_unittests": "e531702a972bdb4caaab0e20be57008da1067286", "snapshot_unittests": "b7a2d9bdffd18e54ff415c41a3da760774cfeacd", "sql_unittests": "a3d87c57d727cf9632ef610c3b86a201e48a0299", "storage_unittests": "fab5ff952e2bac33bfd4d3523bc6f547203025d1", "sync_integration_tests": "0385b60a931ed8734024d5ea029d794385524667", "traffic_annotation_auditor_unittests": "c67d9fe11e5a566302bca9a12130e4c741c8d284", "ui_base_unittests": "7873d9abebc42853e122035d4cc040a6a73ea644", "ui_chromeos_unittests": "f8ed2198ecdf741bc71dab6d71ac413df304a73f", "ui_touch_selection_unittests": "59e67da78e3fcc3ccce02e26d2c8e1b359635655", "unit_tests": "2874a7bbbd2f9889e64df2b1de973d54668479c1", "url_unittests": "fbb72e9f6309a097aeee9673be870833f6a44dab", "usage_time_limit_unittests": "f13edfc7eb9d5fb6f423a6e832f8f39cdc61d1f3", "views_unittests": "57dc91f1b782e443b5f060832ff12151a571c421", "viz_unittests": "2c4a581d32da18c0a23cfffd3def28604d6fadce", "wayland_client_perftests": "48e5b8c88f6816cef63f35c93f1ba015ce9776db", "wm_unittests": "0b26de8b3f70a0fbe117dd1e9a2f50d9e33f6c3e", "wtf_unittests": "682a8a015226b1fd4bf425e0db497d0aca797629"}}', '--summary-json-file', '/b/swarming/w/ir/tmp/t/tmpKpgOAF.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/tmpnQOjML.json'] env: {'CHROME_HEADLESS': '1'} env_prefixes: {'PATH': '/b/swarming/w/ir/cache/swarming_client'} env_suffixes: {} infra_step: False name_tokens: ('cacheinvalidation_unittests',) ok_ret: ALL_OK step_test_data: gen_default_step_test_data(...) 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: 43901 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/8915494057192899376 LOGDOG_STREAM_PROJECT: chromium LOGDOG_STREAM_SERVER_PATH: unix:/b/swarming/w/ir/tmp/ld.sock LOGICAL: eth0 LUCI_CONTEXT: /b/swarming/w/itgycq0y/luci_context.027436703 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: swarm2376-c4 SWARMING_EXTERNAL_BOT_SETUP: 1 SWARMING_HEADLESS: 1 SWARMING_SERVER: https://chromium-swarm.appspot.com SWARMING_TASK_ID: 445cd645ec253011 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-04-22 01:00:08,038 - root: [DEBUG] Using task_output_dir: '/b/swarming/w/ir/tmp/t/tmplF3XKE' 2019-04-22 01:00:08,039 - root: [WARNING] task_output_dir '/b/swarming/w/ir/tmp/t/tmplF3XKE' already exists! 2019-04-22 01:00:08,039 - root: [WARNING] task_output_dir existing content: [] 2019-04-22 01:00:08,039 - 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/tmpnQOjML.json -output-dir /b/swarming/w/ir/tmp/t/tmplF3XKE -task-summary-json /b/swarming/w/ir/tmp/t/tmpKpgOAF.json [D2019-04-22T01:00:08.046415-07:00 26445 0 auth.go:1265] Minting a new token {"key":"luci_ctx/fc07dece103e9305d9cf335d4bc09d96078bd28f3bdde356c855f348dbf31975", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-04-22T01:00:08.046482-07:00 26445 0 luci_ctx.go:138] POST http://127.0.0.1:36457/rpc/LuciLocalAuthService.GetOAuthToken {"key":"luci_ctx/fc07dece103e9305d9cf335d4bc09d96078bd28f3bdde356c855f348dbf31975", "scopes":"https://www.googleapis.com/auth/userinfo.email"} [D2019-04-22T01:00:08.048333-07:00 26445 0 auth.go:1222] Token expires in 39m59.951685609s {"key":"luci_ctx/fc07dece103e9305d9cf335d4bc09d96078bd28f3bdde356c855f348dbf31975", "scopes":"https://www.googleapis.com/auth/userinfo.email"} 445cdd5ff1daed10: exit 0 /b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:354: SNIMissingWarning: An HTTPS request has been made, but the SNI (Server Name Indication) extension to TLS is not available on this platform. This may cause the server to present an incorrect TLS certificate, which can cause validation failures. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings /b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings /b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings /b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings /b/s/swarming_bot.1.zip/third_party/urllib3/util/ssl_.py:150: InsecurePlatformWarning: A true SSLContext object is not available. This prevents urllib3 from configuring SSL appropriately and may cause certain SSL connections to fail. You can upgrade to a newer version of Python to solve this. For more information, see https://urllib3.readthedocs.io/en/latest/advanced-usage.html#ssl-warnings Additional test environment: ASAN_OPTIONS=symbolize=0 handle_abort=1 CHROME_DEVEL_SANDBOX=/opt/chromium/chrome_sandbox CHROME_HEADLESS=1 G_SLICE=always-malloc LANG=en_US.UTF-8 LLVM_SYMBOLIZER_PATH=/b/s/w/ir/third_party/llvm-build/Release+Asserts/bin/llvm-symbolizer NSS_DISABLE_ARENA_FREE_LIST=1 NSS_DISABLE_UNLOAD=1 Command: ./cacheinvalidation_unittests --test-launcher-bot-mode --cfi-diag=0 --test-launcher-print-test-stdio=always --test-launcher-summary-output=/b/s/w/ioZeWlgU/output.json IMPORTANT DEBUGGING NOTE: batches of tests are run inside their own process. For debugging a test inside a debugger, use the --gtest_filter=<your_test_name> flag along with --single-process-tests. Using sharding settings from environment. This is shard 0/1 Using 8 parallel jobs. [ RUN ] ProtocolHandlerTest.TokenMissing [25074:25074:0419/122958.968417:25455491243:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000000ff0 with delay 0 [25074:25074:0419/122958.968637:25455491384:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000000ff0 [25074:25074:0419/122958.969538:25455492282: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 } [25074:25074:0419/122958.969642:25455492382:INFO:recurring-task.cc(55)] [Send-info] Scheduling 17192 with a delay 500000, Now = 210919424 [25074:25074:0419/122958.969738:25455492486:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001030 with delay 500 [25074:25074:0419/122958.969983:25455492725:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001030 [25074:25074:0419/122958.970289:25455493032:WARNING:protocol-handler.cc(375)] Cannot send message since no token and no initialize msg: { } [25074:25074:0419/122958.970418:25455493157:WARNING:protocol-handler.cc(313)] Unable to build message [ OK ] ProtocolHandlerTest.TokenMissing (4 ms) [1/28] ProtocolHandlerTest.TokenMissing (4 ms) [ RUN ] ProtocolHandlerTest.InvalidOutboundMessage [25074:25074:0419/122958.971827:25455494566:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000015b0 with delay 0 [25074:25074:0419/122958.971920:25455494671:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000015b0 [25074:25074:0419/122958.972029:25455494776:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 22184 with a delay 500000, Now = 210919424 [25074:25074:0419/122958.972108:25455494861:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000015d0 with delay 500 [25074:25074:0419/122958.972370:25455495118:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000015d0 [25074:25074:0419/122958.972759:25455495513:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [25074:25074:0419/122958.973015:25455495754: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 } [25074:25074:0419/122958.973146:25455495886: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 } } [25074:25074:0419/122958.973473:25455496223: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 } } } [25074:25074:0419/122958.973717:25455496466: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) [2/28] ProtocolHandlerTest.InvalidOutboundMessage (3 ms) [ RUN ] ProtocolHandlerTest.UnparseableInboundMessage [25074:25074:0419/122958.974646:25455497396:INFO:protocol-handler.cc(139)] Incoming message: { } [25074:25074:0419/122958.974731:25455497473:ERROR:ticl-message-validator.cc(361)] required field header missing from { } [25074:25074:0419/122958.974817:25455497560:ERROR:protocol-handler.cc(145)] Received invalid message: { } [ OK ] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [3/28] ProtocolHandlerTest.UnparseableInboundMessage (1 ms) [ RUN ] RecurringTaskTest.PeriodicTask [25074:25074:0419/122958.975382:25455498130:INFO:recurring-task.cc(55)] [testPeriodicTask] Scheduling -1938922392 with a delay 10000, Now = 0 [25074:25074:0419/122958.975487:25455498224:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000001c90 with delay 10 [25074:25074:0419/122958.975574:25455498319:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000001c90 [25074:25074:0419/122958.975653:25455498398:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [25074:25074:0419/122958.975736:25455498480:INFO:recurring-task.cc(55)] [Retry] Scheduling -1938922392 with a delay 60000, Now = 10000 [25074:25074:0419/122958.975811:25455498561:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000001cb0 with delay 60 [25074:25074:0419/122958.975910:25455498647:INFO:deterministic-scheduler.cc(75)] (Now: 70000) Running task 0x602000001cb0 [25074:25074:0419/122958.975976:25455498718:INFO:recurring-task_test.cc(71)] (70000) Task running: 2 [25074:25074:0419/122958.976025:25455498771:INFO:recurring-task.cc(55)] [Retry] Scheduling -1938922392 with a delay 60000, Now = 70000 [25074:25074:0419/122958.976075:25455498814:INFO:deterministic-scheduler.cc(33)] (Now: 70000) Enqueuing 0x602000001cd0 with delay 60 [25074:25074:0419/122958.976153:25455498893:INFO:deterministic-scheduler.cc(75)] (Now: 130000) Running task 0x602000001cd0 [25074:25074:0419/122958.976193:25455498932:INFO:recurring-task_test.cc(71)] (130000) Task running: 3 [25074:25074:0419/122958.976230:25455498966:INFO:recurring-task.cc(55)] [Retry] Scheduling -1938922392 with a delay 60000, Now = 130000 [25074:25074:0419/122958.976274:25455499013:INFO:deterministic-scheduler.cc(33)] (Now: 130000) Enqueuing 0x602000001cf0 with delay 60 [25074:25074:0419/122958.976348:25455499084:INFO:deterministic-scheduler.cc(75)] (Now: 190000) Running task 0x602000001cf0 [25074:25074:0419/122958.976394:25455499137:INFO:recurring-task_test.cc(71)] (190000) Task running: 4 [25074:25074:0419/122958.976443:25455499182:INFO:recurring-task.cc(55)] [Retry] Scheduling -1938922392 with a delay 60000, Now = 190000 [25074:25074:0419/122958.976485:25455499222:INFO:deterministic-scheduler.cc(33)] (Now: 190000) Enqueuing 0x602000001d10 with delay 60 [25074:25074:0419/122958.976531:25455499270:INFO:deterministic-scheduler.cc(75)] (Now: 250000) Running task 0x602000001d10 [25074:25074:0419/122958.976571:25455499331:INFO:recurring-task_test.cc(71)] (250000) Task running: 5 [25074:25074:0419/122958.976629:25455499374:INFO:recurring-task.cc(55)] [Retry] Scheduling -1938922392 with a delay 60000, Now = 250000 [25074:25074:0419/122958.976688:25455499424:INFO:deterministic-scheduler.cc(33)] (Now: 250000) Enqueuing 0x602000001d30 with delay 60 [25074:25074:0419/122958.976748:25455499484:INFO:deterministic-scheduler.cc(75)] (Now: 310000) Running task 0x602000001d30 [25074:25074:0419/122958.976791:25455499527:INFO:recurring-task_test.cc(71)] (310000) Task running: 6 [25074:25074:0419/122958.976830:25455499572:INFO:recurring-task.cc(55)] [Retry] Scheduling -1938922392 with a delay 60000, Now = 310000 [25074:25074:0419/122958.976890:25455499627:INFO:deterministic-scheduler.cc(33)] (Now: 310000) Enqueuing 0x602000001d50 with delay 60 [25074:25074:0419/122958.976951:25455499693:INFO:deterministic-scheduler.cc(75)] (Now: 370000) Running task 0x602000001d50 [25074:25074:0419/122958.977004:25455499740:INFO:recurring-task_test.cc(71)] (370000) Task running: 7 [25074:25074:0419/122958.977046:25455499793:INFO:recurring-task.cc(55)] [Retry] Scheduling -1938922392 with a delay 60000, Now = 370000 [25074:25074:0419/122958.977101:25455499843:INFO:deterministic-scheduler.cc(33)] (Now: 370000) Enqueuing 0x602000001d70 with delay 60 [25074:25074:0419/122958.977186:25455499925:INFO:deterministic-scheduler.cc(75)] (Now: 430000) Running task 0x602000001d70 [25074:25074:0419/122958.977257:25455500025:INFO:recurring-task_test.cc(71)] (430000) Task running: 8 [ OK ] RecurringTaskTest.PeriodicTask (3 ms) [4/28] RecurringTaskTest.PeriodicTask (3 ms) [ RUN ] RecurringTaskTest.ExponentialBackoffTask [25074:25074:0419/122958.979082:25455501821:INFO:recurring-task.cc(55)] [testExponentialBackoffTask] Scheduling -1939066776 with a delay 10000, Now = 0 [25074:25074:0419/122958.979167:25455501910:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000001df0 with delay 10 [25074:25074:0419/122958.979240:25455501977:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000001df0 [25074:25074:0419/122958.979315:25455502051:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [25074:25074:0419/122958.979377:25455502121:INFO:recurring-task.cc(55)] [Retry] Scheduling -1939066776 with a delay 50000, Now = 10000 [25074:25074:0419/122958.979441:25455502178:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000001e10 with delay 50 [25074:25074:0419/122958.979549:25455502292:INFO:deterministic-scheduler.cc(75)] (Now: 60000) Running task 0x602000001e10 [25074:25074:0419/122958.979628:25455502369:INFO:recurring-task_test.cc(71)] (60000) Task running: 2 [25074:25074:0419/122958.979691:25455502432:INFO:recurring-task.cc(55)] [Retry] Scheduling -1939066776 with a delay 149000, Now = 60000 [25074:25074:0419/122958.979746:25455502486:INFO:deterministic-scheduler.cc(33)] (Now: 60000) Enqueuing 0x602000001e30 with delay 149 [25074:25074:0419/122958.979837:25455502576:INFO:deterministic-scheduler.cc(75)] (Now: 210000) Running task 0x602000001e30 [25074:25074:0419/122958.979887:25455502635:INFO:recurring-task_test.cc(71)] (210000) Task running: 3 [25074:25074:0419/122958.979964:25455502706:INFO:recurring-task.cc(55)] [Retry] Scheduling -1939066776 with a delay 248000, Now = 210000 [25074:25074:0419/122958.980030:25455502770:INFO:deterministic-scheduler.cc(33)] (Now: 210000) Enqueuing 0x602000001e50 with delay 248 [25074:25074:0419/122958.980098:25455502838:INFO:deterministic-scheduler.cc(75)] (Now: 460000) Running task 0x602000001e50 [25074:25074:0419/122958.980149:25455502889:INFO:recurring-task_test.cc(71)] (460000) Task running: 4 [25074:25074:0419/122958.980213:25455502951:INFO:recurring-task.cc(55)] [Retry] Scheduling -1939066776 with a delay 446000, Now = 460000 [25074:25074:0419/122958.980291:25455503038:INFO:deterministic-scheduler.cc(33)] (Now: 460000) Enqueuing 0x602000001e70 with delay 446 [25074:25074:0419/122958.980388:25455503128:INFO:deterministic-scheduler.cc(75)] (Now: 910000) Running task 0x602000001e70 [25074:25074:0419/122958.980454:25455503195:INFO:recurring-task_test.cc(71)] (910000) Task running: 5 [25074:25074:0419/122958.980517:25455503257:INFO:recurring-task.cc(55)] [Retry] Scheduling -1939066776 with a delay 842000, Now = 910000 [25074:25074:0419/122958.980582:25455503322:INFO:deterministic-scheduler.cc(33)] (Now: 910000) Enqueuing 0x602000001e90 with delay 842 [25074:25074:0419/122958.980667:25455503413:INFO:deterministic-scheduler.cc(75)] (Now: 1760000) Running task 0x602000001e90 [25074:25074:0419/122958.980718:25455503452:INFO:recurring-task_test.cc(71)] (1760000) Task running: 6 [25074:25074:0419/122958.980754:25455503494:INFO:recurring-task.cc(55)] [Retry] Scheduling -1939066776 with a delay 1040000, Now = 1760000 [25074:25074:0419/122958.980794:25455503536:INFO:deterministic-scheduler.cc(33)] (Now: 1760000) Enqueuing 0x602000001eb0 with delay 1040 [25074:25074:0419/122958.980869:25455503606:INFO:deterministic-scheduler.cc(75)] (Now: 2800000) Running task 0x602000001eb0 [25074:25074:0419/122958.980905:25455503645:INFO:recurring-task_test.cc(71)] (2800000) Task running: 7 [25074:25074:0419/122958.980946:25455503683:INFO:recurring-task.cc(55)] [Retry] Scheduling -1939066776 with a delay 1040000, Now = 2800000 [25074:25074:0419/122958.980995:25455503731:INFO:deterministic-scheduler.cc(33)] (Now: 2800000) Enqueuing 0x602000001ed0 with delay 1040 [25074:25074:0419/122958.981060:25455503800:INFO:deterministic-scheduler.cc(75)] (Now: 3840000) Running task 0x602000001ed0 [25074:25074:0419/122958.981098:25455503835:INFO:recurring-task_test.cc(71)] (3840000) Task running: 8 [ OK ] RecurringTaskTest.ExponentialBackoffTask (3 ms) [5/28] RecurringTaskTest.ExponentialBackoffTask (3 ms) [ RUN ] RecurringTaskTest.OneShotTask [25074:25074:0419/122958.982132:25455504877:INFO:recurring-task.cc(55)] [testOneShotTask] Scheduling -1939078040 with a delay 10000, Now = 0 [25074:25074:0419/122958.982199:25455504939:INFO:deterministic-scheduler.cc(33)] (Now: 0) Enqueuing 0x602000001f50 with delay 10 [25074:25074:0419/122958.982279:25455505021:INFO:deterministic-scheduler.cc(75)] (Now: 10000) Running task 0x602000001f50 [25074:25074:0419/122958.982352:25455505090:INFO:recurring-task_test.cc(71)] (10000) Task running: 1 [25074:25074:0419/122958.982416:25455505160:INFO:recurring-task.cc(55)] [testOneShotTask-4] Scheduling -1939078040 with a delay 10000, Now = 10000 [25074:25074:0419/122958.982494:25455505231:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000001f70 with delay 10 [25074:25074:0419/122958.982554:25455505291:INFO:deterministic-scheduler.cc(75)] (Now: 20000) Running task 0x602000001f70 [25074:25074:0419/122958.982615:25455505354:INFO:recurring-task_test.cc(71)] (20000) Task running: 2 [ OK ] RecurringTaskTest.OneShotTask (1 ms) [6/28] RecurringTaskTest.OneShotTask (1 ms) [ RUN ] ThrottleTest.ThrottlingScripted [25074:25074:0419/122958.983897:25455506635:INFO:deterministic-scheduler.cc(33)] (Now: 80000) Enqueuing 0x602000001ff0 with delay 920 [25074:25074:0419/122958.984000:25455506752:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000001ff0 [25074:25074:0419/122958.984375:25455507115:INFO:deterministic-scheduler.cc(33)] (Now: 15000000) Enqueuing 0x602000002010 with delay 45000 [25074:25074:0419/122958.985252:25455508019:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002010 [ OK ] ThrottleTest.ThrottlingScripted (2 ms) [7/28] ThrottleTest.ThrottlingScripted (2 ms) [ RUN ] ThrottleTest.ThrottlingStorm [25074:25074:0419/122958.985536:25455508273:INFO:deterministic-scheduler.cc(33)] (Now: 10000) Enqueuing 0x602000002090 with delay 990 [25074:25074:0419/122958.985625:25455508378:INFO:deterministic-scheduler.cc(75)] (Now: 1000000) Running task 0x602000002090 [25074:25074:0419/122958.985706:25455508443:INFO:deterministic-scheduler.cc(33)] (Now: 1000000) Enqueuing 0x6020000020b0 with delay 1000 [25074:25074:0419/122958.985774:25455508511:INFO:deterministic-scheduler.cc(75)] (Now: 2000000) Running task 0x6020000020b0 [25074:25074:0419/122958.985806:25455508546:INFO:deterministic-scheduler.cc(33)] (Now: 2000000) Enqueuing 0x6020000020d0 with delay 1000 [25074:25074:0419/122958.985878:25455508614:INFO:deterministic-scheduler.cc(75)] (Now: 3000000) Running task 0x6020000020d0 [25074:25074:0419/122958.985914:25455508658:INFO:deterministic-scheduler.cc(33)] (Now: 3000000) Enqueuing 0x6020000020f0 with delay 1000 [25074:25074:0419/122958.985987:25455508721:INFO:deterministic-scheduler.cc(75)] (Now: 4000000) Running task 0x6020000020f0 [25074:25074:0419/122958.986020:25455508757:INFO:deterministic-scheduler.cc(33)] (Now: 4000000) Enqueuing 0x602000002110 with delay 1000 [25074:25074:0419/122958.986079:25455508817:INFO:deterministic-scheduler.cc(75)] (Now: 5000000) Running task 0x602000002110 [25074:25074:0419/122958.986118:25455508852:INFO:deterministic-scheduler.cc(33)] (Now: 5000000) Enqueuing 0x602000002130 with delay 1000 [25074:25074:0419/122958.986186:25455508924:INFO:deterministic-scheduler.cc(75)] (Now: 6000000) Running task 0x602000002130 [25074:25074:0419/122958.986227:25455508965:INFO:deterministic-scheduler.cc(33)] (Now: 6000000) Enqueuing 0x602000002150 with delay 54000 [25074:25074:0419/122958.987870:25455510611:INFO:deterministic-scheduler.cc(75)] (Now: 60000000) Running task 0x602000002150 [25074:25074:0419/122958.987923:25455510661:INFO:deterministic-scheduler.cc(33)] (Now: 60000000) Enqueuing 0x602000002170 with delay 1000 [25074:25074:0419/122958.987998:25455510733:INFO:deterministic-scheduler.cc(75)] (Now: 61000000) Running task 0x602000002170 [25074:25074:0419/122958.988035:25455510772:INFO:deterministic-scheduler.cc(33)] (Now: 61000000) Enqueuing 0x602000002190 with delay 1000 [25074:25074:0419/122958.988094:25455510830:INFO:deterministic-scheduler.cc(75)] (Now: 62000000) Running task 0x602000002190 [25074:25074:0419/122958.988131:25455510865:INFO:deterministic-scheduler.cc(33)] (Now: 62000000) Enqueuing 0x6020000021b0 with delay 1000 [25074:25074:0419/122958.988196:25455510934:INFO:deterministic-scheduler.cc(75)] (Now: 63000000) Running task 0x6020000021b0 [25074:25074:0419/122958.988226:25455510972:INFO:deterministic-scheduler.cc(33)] (Now: 63000000) Enqueuing 0x6020000021d0 with delay 1000 [25074:25074:0419/122958.988308:25455511045:INFO:deterministic-scheduler.cc(75)] (Now: 64000000) Running task 0x6020000021d0 [25074:25074:0419/122958.988347:25455511085:INFO:deterministic-scheduler.cc(33)] (Now: 64000000) Enqueuing 0x6020000021f0 with delay 1000 [25074:25074:0419/122958.988415:25455511149:INFO:deterministic-scheduler.cc(75)] (Now: 65000000) Running task 0x6020000021f0 [25074:25074:0419/122958.988447:25455511187:INFO:deterministic-scheduler.cc(33)] (Now: 65000000) Enqueuing 0x602000002210 with delay 1000 [25074:25074:0419/122958.988517:25455511253:INFO:deterministic-scheduler.cc(75)] (Now: 66000000) Running task 0x602000002210 [25074:25074:0419/122958.988557:25455511291:INFO:deterministic-scheduler.cc(33)] (Now: 66000000) Enqueuing 0x602000002230 with delay 54000 [25074:25074:0419/122958.990176:25455512915:INFO:deterministic-scheduler.cc(75)] (Now: 120000000) Running task 0x602000002230 [25074:25074:0419/122958.990218:25455512955:INFO:deterministic-scheduler.cc(33)] (Now: 120000000) Enqueuing 0x602000002250 with delay 1000 [25074:25074:0419/122958.990297:25455513034:INFO:deterministic-scheduler.cc(75)] (Now: 121000000) Running task 0x602000002250 [25074:25074:0419/122958.990324:25455513065:INFO:deterministic-scheduler.cc(33)] (Now: 121000000) Enqueuing 0x602000002270 with delay 1000 [25074:25074:0419/122958.990393:25455513127:INFO:deterministic-scheduler.cc(75)] (Now: 122000000) Running task 0x602000002270 [25074:25074:0419/122958.990420:25455513158:INFO:deterministic-scheduler.cc(33)] (Now: 122000000) Enqueuing 0x602000002290 with delay 1000 [25074:25074:0419/122958.990478:25455513215:INFO:deterministic-scheduler.cc(75)] (Now: 123000000) Running task 0x602000002290 [25074:25074:0419/122958.990506:25455513240:INFO:deterministic-scheduler.cc(33)] (Now: 123000000) Enqueuing 0x6020000022b0 with delay 1000 [25074:25074:0419/122958.990562:25455513299:INFO:deterministic-scheduler.cc(75)] (Now: 124000000) Running task 0x6020000022b0 [25074:25074:0419/122958.990587:25455513328:INFO:deterministic-scheduler.cc(33)] (Now: 124000000) Enqueuing 0x6020000022d0 with delay 1000 [25074:25074:0419/122958.990646:25455513383:INFO:deterministic-scheduler.cc(75)] (Now: 125000000) Running task 0x6020000022d0 [25074:25074:0419/122958.990672:25455513409:INFO:deterministic-scheduler.cc(33)] (Now: 125000000) Enqueuing 0x6020000022f0 with delay 1000 [25074:25074:0419/122958.990729:25455513463:INFO:deterministic-scheduler.cc(75)] (Now: 126000000) Running task 0x6020000022f0 [25074:25074:0419/122958.990755:25455513492:INFO:deterministic-scheduler.cc(33)] (Now: 126000000) Enqueuing 0x602000002310 with delay 54000 [25074:25074:0419/122958.992324:25455515065:INFO:deterministic-scheduler.cc(75)] (Now: 180000000) Running task 0x602000002310 [25074:25074:0419/122958.992376:25455515111:INFO:deterministic-scheduler.cc(33)] (Now: 180000000) Enqueuing 0x602000002330 with delay 1000 [25074:25074:0419/122958.992439:25455515177:INFO:deterministic-scheduler.cc(75)] (Now: 181000000) Running task 0x602000002330 [25074:25074:0419/122958.992486:25455515223:INFO:deterministic-scheduler.cc(33)] (Now: 181000000) Enqueuing 0x602000002350 with delay 1000 [25074:25074:0419/122958.992551:25455515288:INFO:deterministic-scheduler.cc(75)] (Now: 182000000) Running task 0x602000002350 [25074:25074:0419/122958.992580:25455515317:INFO:deterministic-scheduler.cc(33)] (Now: 182000000) Enqueuing 0x602000002370 with delay 1000 [25074:25074:0419/122958.992639:25455515373:INFO:deterministic-scheduler.cc(75)] (Now: 183000000) Running task 0x602000002370 [25074:25074:0419/122958.992668:25455515406:INFO:deterministic-scheduler.cc(33)] (Now: 183000000) Enqueuing 0x602000002390 with delay 1000 [25074:25074:0419/122958.992724:25455515461:INFO:deterministic-scheduler.cc(75)] (Now: 184000000) Running task 0x602000002390 [25074:25074:0419/122958.992755:25455515489:INFO:deterministic-scheduler.cc(33)] (Now: 184000000) Enqueuing 0x6020000023b0 with delay 1000 [25074:25074:0419/122958.992809:25455515547:INFO:deterministic-scheduler.cc(75)] (Now: 185000000) Running task 0x6020000023b0 [25074:25074:0419/122958.992837:25455515579:INFO:deterministic-scheduler.cc(33)] (Now: 185000000) Enqueuing 0x6020000023d0 with delay 1000 [25074:25074:0419/122958.992897:25455515637:INFO:deterministic-scheduler.cc(75)] (Now: 186000000) Running task 0x6020000023d0 [25074:25074:0419/122958.992930:25455515668:INFO:deterministic-scheduler.cc(33)] (Now: 186000000) Enqueuing 0x6020000023f0 with delay 54000 [25074:25074:0419/122958.994552:25455517288:INFO:deterministic-scheduler.cc(75)] (Now: 240000000) Running task 0x6020000023f0 [25074:25074:0419/122958.994591:25455517328:INFO:deterministic-scheduler.cc(33)] (Now: 240000000) Enqueuing 0x602000002410 with delay 1000 [25074:25074:0419/122958.994644:25455517387:INFO:deterministic-scheduler.cc(75)] (Now: 241000000) Running task 0x602000002410 [25074:25074:0419/122958.994683:25455517418:INFO:deterministic-scheduler.cc(33)] (Now: 241000000) Enqueuing 0x602000002430 with delay 1000 [25074:25074:0419/122958.994750:25455517496:INFO:deterministic-scheduler.cc(75)] (Now: 242000000) Running task 0x602000002430 [25074:25074:0419/122958.994785:25455517522:INFO:deterministic-scheduler.cc(33)] (Now: 242000000) Enqueuing 0x602000002450 with delay 1000 [25074:25074:0419/122958.994852:25455517588:INFO:deterministic-scheduler.cc(75)] (Now: 243000000) Running task 0x602000002450 [25074:25074:0419/122958.994883:25455517619:INFO:deterministic-scheduler.cc(33)] (Now: 243000000) Enqueuing 0x602000002470 with delay 1000 [25074:25074:0419/122958.994938:25455517672:INFO:deterministic-scheduler.cc(75)] (Now: 244000000) Running task 0x602000002470 [25074:25074:0419/122958.994963:25455517697:INFO:deterministic-scheduler.cc(33)] (Now: 244000000) Enqueuing 0x602000002490 with delay 1000 [25074:25074:0419/122958.995018:25455517752:INFO:deterministic-scheduler.cc(75)] (Now: 245000000) Running task 0x602000002490 [25074:25074:0419/122958.995040:25455517774:INFO:deterministic-scheduler.cc(33)] (Now: 245000000) Enqueuing 0x6020000024b0 with delay 1000 [25074:25074:0419/122958.995099:25455517842:INFO:deterministic-scheduler.cc(75)] (Now: 246000000) Running task 0x6020000024b0 [25074:25074:0419/122958.995141:25455517877:INFO:deterministic-scheduler.cc(33)] (Now: 246000000) Enqueuing 0x6020000024d0 with delay 54000 [25074:25074:0419/122958.996760:25455519499:INFO:deterministic-scheduler.cc(75)] (Now: 300000000) Running task 0x6020000024d0 [ OK ] ThrottleTest.ThrottlingStorm (11 ms) [8/28] ThrottleTest.ThrottlingStorm (11 ms) [ RUN ] ProtocolHandlerTest.SendInitializeOnly [25073:25073:0419/122958.967204:25455490066:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000000ff0 with delay 0 [25073:25073:0419/122958.968645:25455491407:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000000ff0 [25073:25073:0419/122958.969662:25455492413: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 } [25073:25073:0419/122958.969822:25455492566:INFO:recurring-task.cc(55)] [Startup] Scheduling 17192 with a delay 500000, Now = 210919424 [25073:25073:0419/122958.969943:25455492696:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000011b0 with delay 500 [25073:25073:0419/122958.970276:25455493031:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000011b0 [25073:25073:0419/122958.971019:25455493770:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777600500 max_known_server_time_ms: 0 message_id: "1" } initialize_message: { client_type: 2 nonce: "unit-test-nonce" application_client_id: { client_type: 2 client_name: "unit-test-client-id" } digest_serialization_type: BYTE_BASED } } [ OK ] ProtocolHandlerTest.SendInitializeOnly (8 ms) [9/28] ProtocolHandlerTest.SendInitializeOnly (8 ms) [ RUN ] ProtocolHandlerTest.ReceiveTokenControlOnly [25073:25073:0419/122958.974638:25455497387: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) [10/28] ProtocolHandlerTest.ReceiveTokenControlOnly (2 ms) [ RUN ] ProtocolHandlerTest.SendMultipleMessageTypes [25073:25073:0419/122958.975851:25455498592:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001df0 with delay 0 [25073:25073:0419/122958.976037:25455498798:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e10 with delay 0 [25073:25073:0419/122958.976171:25455498919:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e30 with delay 0 [25073:25073:0419/122958.976330:25455499088:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e50 with delay 0 [25073:25073:0419/122958.976433:25455499181:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e70 with delay 0 [25073:25073:0419/122958.976556:25455499300:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001e90 with delay 0 [25073:25073:0419/122958.977609:25455500360:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001df0 [25073:25073:0419/122958.977851:25455500588: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 } [25073:25073:0419/122958.977966:25455500706:INFO:recurring-task.cc(55)] [Send-info] Scheduling 28712 with a delay 500000, Now = 210919424 [25073:25073:0419/122958.978038:25455500780:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002030 with delay 500 [25073:25073:0419/122958.978113:25455500847:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001e10 [25073:25073:0419/122958.978175:25455500920:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001e30 [25073:25073:0419/122958.978228:25455500975:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001e50 [25073:25073:0419/122958.978303:25455501042:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001e70 [25073:25073:0419/122958.978351:25455501086:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001e90 [25073:25073:0419/122958.978437:25455501187:INFO:protocol-handler.cc(294)] Adding subtree: { registered_object: { source: 2 name: "oid0" } } [25073:25073:0419/122958.978695:25455501436:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000002030 [25073:25073:0419/122958.979050:25455501789:INFO:protocol-handler.cc(352)] Sending token on client->server message: "test token" [25073:25073:0419/122958.979915:25455502666: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) [11/28] ProtocolHandlerTest.SendMultipleMessageTypes (6 ms) [ RUN ] ProtocolHandlerTest.IncomingCompositeMessage [25073:25073:0419/122958.982859:25455505603: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) [12/28] ProtocolHandlerTest.IncomingCompositeMessage (2 ms) [ RUN ] ProtocolHandlerTest.InvalidInboundMessage [25073:25073:0419/122958.983912:25455506658: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 } } [25073:25073:0419/122958.984034:25455506780: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" } [25073:25073:0419/122958.984215:25455506958: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 } } [25073:25073:0419/122958.984410:25455507159:ERROR:protocol-handler.cc(145)] Received invalid message: { header: { client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } [ OK ] ProtocolHandlerTest.InvalidInboundMessage (1 ms) [13/28] ProtocolHandlerTest.InvalidInboundMessage (1 ms) [ RUN ] ProtocolHandlerTest.MajorVersionMismatch [25073:25073:0419/122958.985293:25455508038: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 } } [25073:25073:0419/122958.985507:25455508245:ERROR:protocol-handler.cc(156)] Dropping message with incompatible version: { header: { protocol_version: { version: { major_version: 1 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } info_request_message: { info_type: GET_PERFORMANCE_COUNTERS } } [ OK ] ProtocolHandlerTest.MajorVersionMismatch (1 ms) [14/28] ProtocolHandlerTest.MajorVersionMismatch (1 ms) [ RUN ] ProtocolHandlerTest.MinorVersionMismatch [25073:25073:0419/122958.986173:25455508918: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) [15/28] ProtocolHandlerTest.MinorVersionMismatch (1 ms) [ RUN ] ProtocolHandlerTest.ConfigMessage [25073:25073:0419/122958.986820:25455509562: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" } } [25073:25073:0419/122958.986914:25455509653:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003b70 with delay 0 [25073:25073:0419/122958.986966:25455509701:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003b70 [25073:25073:0419/122958.987091:25455509827: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 } [25073:25073:0419/122958.987167:25455509905:INFO:recurring-task.cc(55)] [Send-info] Scheduling 59816 with a delay 500000, Now = 210919424 [25073:25073:0419/122958.987213:25455509956:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003b90 with delay 500 [25073:25073:0419/122958.987415:25455510154:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000003b90 [25073:25073:0419/122958.987504:25455510244:WARNING:protocol-handler.cc(306)] In quiet period: not sending message to server: 779600000 > 777600500 [ OK ] ProtocolHandlerTest.ConfigMessage (37 ms) [16/28] ProtocolHandlerTest.ConfigMessage (37 ms) [ RUN ] ProtocolHandlerTest.ErrorMessage [25073:25073:0419/122959.024234:25455546975:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.ErrorMessage (1 ms) [17/28] ProtocolHandlerTest.ErrorMessage (1 ms) [ RUN ] ProtocolHandlerTest.TokenMismatch [25073:25073:0419/122959.024903:25455547647:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "test token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } server_time_ms: 314159265 message_id: "message-id-for-test" } } [ OK ] ProtocolHandlerTest.TokenMismatch (1 ms) [18/28] ProtocolHandlerTest.TokenMismatch (1 ms) [ RUN ] InvalidationClientImplTest.Start [25071:25071:0419/122958.967071:25455490035:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001330 with delay 0 [25071:25071:0419/122958.968431:25455491183:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [25071:25071:0419/122958.969655:25455492417:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001870 with delay 0 [25071:25071:0419/122958.969796:25455492548:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001330 [25071:25071:0419/122958.969916:25455492664:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001870 [25071:25071:0419/122958.970168:25455492913:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [25071:25071:0419/122958.970717:25455493469:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001930 with delay 0 [25071:25071:0419/122958.970880:25455493628:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001930 [25071:25071:0419/122958.970965:25455493722:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [25071:25071:0419/122958.971093:25455493841:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001970 with delay 0 [25071:25071:0419/122958.971188:25455493926:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001970 [25071:25071:0419/122958.971325:25455494077:INFO:invalidation-client-core.cc(351)] Starting with no previous state [25071:25071:0419/122958.971490:25455494235:INFO:recurring-task.cc(55)] [Startup] Scheduling 17448 with a delay 0, Now = 210919424 [25071:25071:0419/122958.971629:25455494383:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000001990 with delay 0 [25071:25071:0419/122958.971727:25455494476:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000001990 [25071:25071:0419/122958.971906:25455494654:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-556201000225343901" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [25071:25071:0419/122958.972022:25455494763:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 17704 with a delay 500000, Now = 210919424 [25071:25071:0419/122958.972130:25455494885:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000019b0 with delay 500 [25071:25071:0419/122958.972227:25455494972:INFO:recurring-task.cc(55)] [Retry] Scheduling 17448 with a delay 60000000, Now = 210919424 [25071:25071:0419/122958.972380:25455495120:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000019d0 with delay 60000 [25071:25071:0419/122958.972691:25455495451:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000019b0 [25071:25071:0419/122958.972849:25455495602:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122958.973054:25455495796:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122958.973459:25455496203: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: "-556201000225343901" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [25071:25071:0419/122958.973885:25455496633:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001a70 with delay 0 [25071:25071:0419/122958.974022:25455496782:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001a70 [25071:25071:0419/122958.974486:25455497233:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-556201000225343901" 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" } } [25071:25071:0419/122958.974691:25455497450:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-556201000225343901" [25071:25071:0419/122958.974802:25455497557:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [25071:25071:0419/122958.974946:25455497694:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 13096 with a delay 1200000000, Now = 211419424 [25071:25071:0419/122958.975052:25455497808:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001a90 with delay 1200000 [25071:25071:0419/122958.975244:25455497989:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [25071:25071:0419/122958.975896:25455498648:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [25071:25071:0419/122958.976021:25455498774:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 3528 with a delay 0, Now = 211419424 [25071:25071:0419/122958.976122:25455498871:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001cb0 with delay 0 [25071:25071:0419/122958.976301:25455499051: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 [25071:25071:0419/122958.976438:25455499185:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001cb0 [25071:25071:0419/122958.976859:25455499621:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001d70 with delay 0 [25071:25071:0419/122958.977010:25455499754:INFO:recurring-task.cc(55)] [Retry] Scheduling 3528 with a delay 10000000, Now = 211419424 [25071:25071:0419/122958.977105:25455499853:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000001db0 with delay 10000 [25071:25071:0419/122958.977237:25455499988:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000001d70 [25071:25071:0419/122958.977517:25455500268:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [ OK ] InvalidationClientImplTest.Start (15 ms) [19/28] InvalidationClientImplTest.Start (15 ms) [ RUN ] InvalidationClientImplTest.GenerateNonce [25071:25071:0419/122958.979220:25455501963:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002610 with delay 0 [25071:25071:0419/122958.979325:25455502064: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 [25071:25071:0419/122958.980150:25455502890:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000002eb0 with delay 0 [25071:25071:0419/122958.980218:25455502963:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [25071:25071:0419/122958.980893:25455503636:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003510 with delay 0 [25071:25071:0419/122958.980966:25455503706:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000002eb0 [25071:25071:0419/122958.981028:25455503765:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003510 [25071:25071:0419/122958.981126:25455503867:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [25071:25071:0419/122958.981247:25455503985:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000035d0 with delay 0 [25071:25071:0419/122958.981348:25455504092:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000035d0 [25071:25071:0419/122958.981406:25455504144:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [25071:25071:0419/122958.981480:25455504226:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003610 with delay 0 [25071:25071:0419/122958.981548:25455504288:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003610 [25071:25071:0419/122958.981591:25455504336:INFO:invalidation-client-core.cc(351)] Starting with no previous state [25071:25071:0419/122958.981666:25455504405:INFO:recurring-task.cc(55)] [Startup] Scheduling 41384 with a delay 0, Now = 210919424 [25071:25071:0419/122958.981732:25455504472:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003630 with delay 0 [25071:25071:0419/122958.981799:25455504546:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000003630 [25071:25071:0419/122958.981899:25455504638:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-8766045093464794656" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [25071:25071:0419/122958.981954:25455504699:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 41640 with a delay 500000, Now = 210919424 [25071:25071:0419/122958.982018:25455504767:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003650 with delay 500 [25071:25071:0419/122958.982075:25455504814:INFO:recurring-task.cc(55)] [Retry] Scheduling 41384 with a delay 60000000, Now = 210919424 [25071:25071:0419/122958.982120:25455504860:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000003670 with delay 60000 [25071:25071:0419/122958.982321:25455505058:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000003650 [25071:25071:0419/122958.982372:25455505113:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122958.982458:25455505197:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122958.982681:25455505427: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: "-8766045093464794656" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [25071:25071:0419/122958.982864:25455505605:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003710 with delay 0 [25071:25071:0419/122958.982917:25455505656:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000003710 [25071:25071:0419/122958.983093:25455505835:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-8766045093464794656" 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" } } [25071:25071:0419/122958.983195:25455505934:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-8766045093464794656" [25071:25071:0419/122958.983247:25455506007:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [25071:25071:0419/122958.983322:25455506068:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 15384 with a delay 1200000000, Now = 211419424 [25071:25071:0419/122958.983391:25455506131:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003730 with delay 1200000 [25071:25071:0419/122958.983455:25455506192:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [25071:25071:0419/122958.983691:25455506427:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [25071:25071:0419/122958.983743:25455506488:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 7944 with a delay 0, Now = 211419424 [25071:25071:0419/122958.983801:25455506544:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003950 with delay 0 [25071:25071:0419/122958.983910:25455506647: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 [25071:25071:0419/122958.983961:25455506697:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000003950 [25071:25071:0419/122958.984115:25455506853:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003a10 with delay 0 [25071:25071:0419/122958.984194:25455506933:INFO:recurring-task.cc(55)] [Retry] Scheduling 7944 with a delay 10000000, Now = 211419424 [25071:25071:0419/122958.984243:25455506982:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000003a50 with delay 10000 [25071:25071:0419/122958.984317:25455507054:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000003a10 [25071:25071:0419/122958.984357:25455507096:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [25071:25071:0419/122958.984448:25455507185:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000003a70 with delay 0 [25071:25071:0419/122958.984501:25455507238:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000003a70 [25071:25071:0419/122958.984569:25455507309:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [25071:25071:0419/122958.984630:25455507368:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid1" }, 1 [25071:25071:0419/122958.984666:25455507403:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid2" }, 1 [25071:25071:0419/122958.984754:25455507493:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 41640 with a delay 500000, Now = 211469424 [25071:25071:0419/122958.984807:25455507544:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000003a90 with delay 500 [25071:25071:0419/122958.984851:25455507587:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 41512 with a delay 60000000, Now = 211469424 [25071:25071:0419/122958.984913:25455507652:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000003ab0 with delay 60000 [25071:25071:0419/122958.985115:25455507855:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000003a90 [25071:25071:0419/122958.985163:25455507905:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122958.985255:25455508017:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122958.985348:25455508084:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [25071:25071:0419/122958.985541:25455508279: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 } } } [25071:25071:0419/122958.985681:25455508419:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122958.985805:25455508543:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000003b50 with delay 0 [25071:25071:0419/122958.985858:25455508593:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000003b50 [25071:25071:0419/122958.986147:25455508885: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 } } } } [25071:25071:0419/122958.986298:25455509038: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 [25071:25071:0419/122958.986546:25455509284:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid0" } op_type: REGISTER } status: { code: SUCCESS } } [25071:25071:0419/122958.986777:25455509519:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid1" } op_type: REGISTER } status: { code: SUCCESS } } [25071:25071:0419/122958.986865:25455509604:INFO:invalidation-client-core.cc(663)] Process reg status: { registration: { object_id: { source: 2 name: "oid2" } op_type: REGISTER } status: { code: SUCCESS } } [25071:25071:0419/122958.987384:25455510132:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000003a50 [ OK ] InvalidationClientImplTest.Register (9 ms) [21/28] InvalidationClientImplTest.Register (9 ms) [ RUN ] InvalidationClientImplTest.Invalidations [25071:25071:0419/122958.989115:25455511858:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004730 with delay 0 [25071:25071:0419/122958.989190:25455511925:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [25071:25071:0419/122958.989751:25455512489:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004e10 with delay 0 [25071:25071:0419/122958.989800:25455512535:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004730 [25071:25071:0419/122958.989847:25455512587:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004e10 [25071:25071:0419/122958.989914:25455512651:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [25071:25071:0419/122958.989988:25455512722:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004ed0 with delay 0 [25071:25071:0419/122958.990039:25455512776:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004ed0 [25071:25071:0419/122958.990072:25455512810:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [25071:25071:0419/122958.990135:25455512869:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004f10 with delay 0 [25071:25071:0419/122958.990170:25455512907:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004f10 [25071:25071:0419/122958.990202:25455512947:INFO:invalidation-client-core.cc(351)] Starting with no previous state [25071:25071:0419/122958.990251:25455512988:INFO:recurring-task.cc(55)] [Startup] Scheduling 72488 with a delay 0, Now = 210919424 [25071:25071:0419/122958.990301:25455513038:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004f30 with delay 0 [25071:25071:0419/122958.990340:25455513076:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000004f30 [25071:25071:0419/122958.990414:25455513151:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "847929053974983682" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [25071:25071:0419/122958.990464:25455513201:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 72744 with a delay 500000, Now = 210919424 [25071:25071:0419/122958.990494:25455513232:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004f50 with delay 500 [25071:25071:0419/122958.990539:25455513273:INFO:recurring-task.cc(55)] [Retry] Scheduling 72488 with a delay 60000000, Now = 210919424 [25071:25071:0419/122958.990576:25455513314:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000004f70 with delay 60000 [25071:25071:0419/122958.990627:25455513364:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000004f50 [25071:25071:0419/122958.990660:25455513402:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122958.990734:25455513473:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122958.990884:25455513621: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: "847929053974983682" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [25071:25071:0419/122958.991037:25455513775:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005010 with delay 0 [25071:25071:0419/122958.991070:25455513810:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005010 [25071:25071:0419/122958.991216:25455513954:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "847929053974983682" 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" } } [25071:25071:0419/122958.991299:25455514038:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "847929053974983682" [25071:25071:0419/122958.991351:25455514089:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [25071:25071:0419/122958.991393:25455514131:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 20488 with a delay 1200000000, Now = 211419424 [25071:25071:0419/122958.991435:25455514172:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005030 with delay 1200000 [25071:25071:0419/122958.991476:25455514211:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [25071:25071:0419/122958.991650:25455514385:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [25071:25071:0419/122958.991688:25455514423:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 14664 with a delay 0, Now = 211419424 [25071:25071:0419/122958.991722:25455514456:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005250 with delay 0 [25071:25071:0419/122958.991768:25455514504: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 [25071:25071:0419/122958.991813:25455514548:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005250 [25071:25071:0419/122958.991874:25455514608:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005310 with delay 0 [25071:25071:0419/122958.991945:25455514681:INFO:recurring-task.cc(55)] [Retry] Scheduling 14664 with a delay 10000000, Now = 211419424 [25071:25071:0419/122958.992008:25455514744:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000005350 with delay 10000 [25071:25071:0419/122958.992040:25455514774:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000005310 [25071:25071:0419/122958.992062:25455514798:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [25071:25071:0419/122958.992121:25455514857:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122958.992174:25455514909:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000005370 with delay 0 [25071:25071:0419/122958.992200:25455514936:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000005370 [25071:25071:0419/122958.992446:25455515182: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 } } } [25071:25071:0419/122958.992548:25455515283: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 [25071:25071:0419/122958.992639:25455515374: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" } [25071:25071:0419/122958.992784:25455515518:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } [25071:25071:0419/122958.992861:25455515596:INFO:invalidation-client-core.cc(630)] Issuing invalidate: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } [25071:25071:0419/122958.992997:25455515734:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000005750 with delay 0 [25071:25071:0419/122958.993032:25455515768:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000005770 with delay 0 [25071:25071:0419/122958.993062:25455515796:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x602000005790 with delay 0 [25071:25071:0419/122958.993090:25455515826:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000005750 [25071:25071:0419/122958.993142:25455515878:INFO:recurring-task.cc(55)] [Send-ack] Scheduling 72744 with a delay 500000, Now = 211519424 [25071:25071:0419/122958.993176:25455515910:INFO:deterministic-scheduler.cc(33)] (Now: 211519424) Enqueuing 0x6020000057b0 with delay 500 [25071:25071:0419/122958.993206:25455515942:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000005770 [25071:25071:0419/122958.993234:25455515969:INFO:deterministic-scheduler.cc(75)] (Now: 211519424) Running task 0x602000005790 [25071:25071:0419/122958.993308:25455516043:INFO:deterministic-scheduler.cc(75)] (Now: 212019424) Running task 0x6020000057b0 [25071:25071:0419/122958.993345:25455516081:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122958.993400:25455516134:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122958.993435:25455516171:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [25071:25071:0419/122958.993605:25455516346:INFO:protocol-handler.cc(330)] Sending message to server: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "new token" registration_summary: { num_registrations: 0 registration_digest: "\3329\243\356^kK\r2U\277\357\225`\030\220\257\330\007\t" } client_time_ms: 777601100 max_known_server_time_ms: 314159265 message_id: "2" } invalidation_ack_message: { invalidation: { object_id: { source: 2 name: "oid0" } is_known_version: true version: 100 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid1" } is_known_version: true version: 119 is_trickle_restart: true } invalidation: { object_id: { source: 2 name: "oid2" } is_known_version: true version: 107 is_trickle_restart: true } } } [ OK ] InvalidationClientImplTest.Invalidations (6 ms) [22/28] InvalidationClientImplTest.Invalidations (6 ms) [ RUN ] InvalidationClientImplTest.ServerRequests [25071:25071:0419/122958.994367:25455517104:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006090 with delay 0 [25071:25071:0419/122958.994416:25455517156:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [25071:25071:0419/122958.994651:25455517388:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000065b0 with delay 0 [25071:25071:0419/122958.994686:25455517425:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006090 [25071:25071:0419/122958.994721:25455517456:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000065b0 [25071:25071:0419/122958.994773:25455517508:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [25071:25071:0419/122958.994827:25455517562:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006670 with delay 0 [25071:25071:0419/122958.994873:25455517607:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000006670 [25071:25071:0419/122958.994899:25455517634:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [25071:25071:0419/122958.994928:25455517663:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000066b0 with delay 0 [25071:25071:0419/122958.994953:25455517688:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000066b0 [25071:25071:0419/122958.994975:25455517711:INFO:invalidation-client-core.cc(351)] Starting with no previous state [25071:25071:0419/122958.995006:25455517741:INFO:recurring-task.cc(55)] [Startup] Scheduling 102184 with a delay 0, Now = 210919424 [25071:25071:0419/122958.995043:25455517779:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000066d0 with delay 0 [25071:25071:0419/122958.995070:25455517806:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000066d0 [25071:25071:0419/122958.995136:25455517871:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-7836975935891755295" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [25071:25071:0419/122958.995178:25455517912:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 102440 with a delay 500000, Now = 210919424 [25071:25071:0419/122958.995204:25455517943:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000066f0 with delay 500 [25071:25071:0419/122958.995239:25455517973:INFO:recurring-task.cc(55)] [Retry] Scheduling 102184 with a delay 60000000, Now = 210919424 [25071:25071:0419/122958.995290:25455518025:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000006710 with delay 60000 [25071:25071:0419/122958.995334:25455518069:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000066f0 [25071:25071:0419/122958.995361:25455518096:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122958.995404:25455518139:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122958.995528:25455518263: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: "-7836975935891755295" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [25071:25071:0419/122958.995650:25455518385:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000067b0 with delay 0 [25071:25071:0419/122958.995711:25455518445:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000067b0 [25071:25071:0419/122958.995812:25455518547:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-7836975935891755295" 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" } } [25071:25071:0419/122958.995862:25455518597:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-7836975935891755295" [25071:25071:0419/122958.995890:25455518625:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [25071:25071:0419/122958.995930:25455518665:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 24536 with a delay 1200000000, Now = 211419424 [25071:25071:0419/122958.995958:25455518693:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000067d0 with delay 1200000 [25071:25071:0419/122958.995998:25455518732:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [25071:25071:0419/122958.996147:25455518882:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [25071:25071:0419/122958.996180:25455518915:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 20808 with a delay 0, Now = 211419424 [25071:25071:0419/122958.996207:25455518946:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x6020000069f0 with delay 0 [25071:25071:0419/122958.996252:25455519002: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 [25071:25071:0419/122958.996303:25455519038:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x6020000069f0 [25071:25071:0419/122958.996368:25455519103:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000006ab0 with delay 0 [25071:25071:0419/122958.996414:25455519148:INFO:recurring-task.cc(55)] [Retry] Scheduling 20808 with a delay 10000000, Now = 211419424 [25071:25071:0419/122958.996459:25455519194:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000006af0 with delay 10000 [25071:25071:0419/122958.996488:25455519224:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000006ab0 [25071:25071:0419/122958.996511:25455519247:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [25071:25071:0419/122958.996554:25455519289:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122958.996604:25455519345:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000006b10 with delay 0 [25071:25071:0419/122958.996660:25455519395:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000006b10 [25071:25071:0419/122958.996772:25455519508: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 } } [25071:25071:0419/122958.996838:25455519573: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 [25071:25071:0419/122958.996876:25455519610:INFO:protocol-handler.cc(294)] Adding subtree: { } [25071:25071:0419/122958.996908:25455519643:INFO:recurring-task.cc(55)] [Send-reg-sync] Scheduling 102440 with a delay 500000, Now = 211469424 [25071:25071:0419/122958.996936:25455519671:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000006b30 with delay 500 [25071:25071:0419/122958.997014:25455519748:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [25071:25071:0419/122958.997203:25455519939: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 } [25071:25071:0419/122958.997299:25455520035:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000006b30 [25071:25071:0419/122958.997334:25455520069:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122958.997412:25455520148:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122958.997443:25455520179:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [25071:25071:0419/122958.997753:25455520489: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 } } [25071:25071:0419/122958.998072:25455520808:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000006af0 [ OK ] InvalidationClientImplTest.ServerRequests (5 ms) [23/28] InvalidationClientImplTest.ServerRequests (5 ms) [ RUN ] InvalidationClientImplTest.IncomingErrorMessage [25071:25071:0419/122958.999469:25455522206:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007410 with delay 0 [25071:25071:0419/122958.999521:25455522257:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [25071:25071:0419/122958.999834:25455522569:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x6020000079d0 with delay 0 [25071:25071:0419/122958.999866:25455522600:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007410 [25071:25071:0419/122958.999890:25455522625:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x6020000079d0 [25071:25071:0419/122958.999937:25455522671:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [25071:25071:0419/122958.999991:25455522726:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007a90 with delay 0 [25071:25071:0419/122959.000026:25455522761:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007a90 [25071:25071:0419/122959.000048:25455522782:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [25071:25071:0419/122959.000086:25455522821:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007ad0 with delay 0 [25071:25071:0419/122959.000124:25455522858:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007ad0 [25071:25071:0419/122959.000152:25455522886:INFO:invalidation-client-core.cc(351)] Starting with no previous state [25071:25071:0419/122959.000180:25455522915:INFO:recurring-task.cc(55)] [Startup] Scheduling 129448 with a delay 0, Now = 210919424 [25071:25071:0419/122959.000208:25455522943:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007af0 with delay 0 [25071:25071:0419/122959.000240:25455522974:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000007af0 [25071:25071:0419/122959.000304:25455523038:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-7780332079374340678" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [25071:25071:0419/122959.000343:25455523078:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 129704 with a delay 500000, Now = 210919424 [25071:25071:0419/122959.000378:25455523113:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007b10 with delay 500 [25071:25071:0419/122959.000405:25455523140:INFO:recurring-task.cc(55)] [Retry] Scheduling 129448 with a delay 60000000, Now = 210919424 [25071:25071:0419/122959.000429:25455523164:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000007b30 with delay 60000 [25071:25071:0419/122959.000473:25455523208:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007b10 [25071:25071:0419/122959.000501:25455523236:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122959.000550:25455523285:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122959.000675:25455523410: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: "-7780332079374340678" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [25071:25071:0419/122959.000774:25455523509:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007bd0 with delay 0 [25071:25071:0419/122959.000806:25455523541:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007bd0 [25071:25071:0419/122959.000905:25455523641:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-7780332079374340678" 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" } } [25071:25071:0419/122959.000965:25455523700:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-7780332079374340678" [25071:25071:0419/122959.000990:25455523725:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [25071:25071:0419/122959.001023:25455523758:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 28056 with a delay 1200000000, Now = 211419424 [25071:25071:0419/122959.001051:25455523785:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007bf0 with delay 1200000 [25071:25071:0419/122959.001083:25455523818:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [25071:25071:0419/122959.001219:25455523954:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [25071:25071:0419/122959.001255:25455524000:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 26184 with a delay 0, Now = 211419424 [25071:25071:0419/122959.001314:25455524048:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007e10 with delay 0 [25071:25071:0419/122959.001359:25455524093: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 [25071:25071:0419/122959.001399:25455524133:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007e10 [25071:25071:0419/122959.001455:25455524190:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007ed0 with delay 0 [25071:25071:0419/122959.001489:25455524224:INFO:recurring-task.cc(55)] [Retry] Scheduling 26184 with a delay 10000000, Now = 211419424 [25071:25071:0419/122959.001532:25455524274:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000007f10 with delay 10000 [25071:25071:0419/122959.001569:25455524303:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000007ed0 [25071:25071:0419/122959.001594:25455524329:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [25071:25071:0419/122959.001649:25455524384:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122959.001694:25455524429:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000007f30 with delay 0 [25071:25071:0419/122959.001720:25455524455:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000007f30 [25071:25071:0419/122959.001815:25455524549: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" } } [25071:25071:0419/122959.001888:25455524624: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 [25071:25071:0419/122959.001916:25455524652:ERROR:invalidation-client-core.cc(723)] Received error message: UNKNOWN_FAILURE, Some error message [25071:25071:0419/122959.002297:25455525034:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000007f10 [ OK ] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [24/28] InvalidationClientImplTest.IncomingErrorMessage (4 ms) [ RUN ] InvalidationClientImplTest.IncomingAuthErrorMessage [25071:25071:0419/122959.003604:25455526349:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008890 with delay 0 [25071:25071:0419/122959.003664:25455526398:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [25071:25071:0419/122959.003956:25455526691:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008f10 with delay 0 [25071:25071:0419/122959.003994:25455526729:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008890 [25071:25071:0419/122959.004026:25455526761:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008f10 [25071:25071:0419/122959.004072:25455526807:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [25071:25071:0419/122959.004135:25455526870:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000008fd0 with delay 0 [25071:25071:0419/122959.004177:25455526912:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000008fd0 [25071:25071:0419/122959.004200:25455526935:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [25071:25071:0419/122959.004234:25455526969:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009010 with delay 0 [25071:25071:0419/122959.004277:25455527012:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009010 [25071:25071:0419/122959.004299:25455527034:INFO:invalidation-client-core.cc(351)] Starting with no previous state [25071:25071:0419/122959.004328:25455527063:INFO:recurring-task.cc(55)] [Startup] Scheduling 152104 with a delay 0, Now = 210919424 [25071:25071:0419/122959.004359:25455527094:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009030 with delay 0 [25071:25071:0419/122959.004384:25455527119:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009030 [25071:25071:0419/122959.004446:25455527180:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "1204921504112226982" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [25071:25071:0419/122959.004480:25455527216:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 152360 with a delay 500000, Now = 210919424 [25071:25071:0419/122959.004520:25455527255:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009050 with delay 500 [25071:25071:0419/122959.004552:25455527288:INFO:recurring-task.cc(55)] [Retry] Scheduling 152104 with a delay 60000000, Now = 210919424 [25071:25071:0419/122959.004584:25455527320:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009070 with delay 60000 [25071:25071:0419/122959.004632:25455527367:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009050 [25071:25071:0419/122959.004657:25455527393:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122959.004693:25455527432:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122959.004831:25455527566: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: "1204921504112226982" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [25071:25071:0419/122959.004950:25455527685:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009110 with delay 0 [25071:25071:0419/122959.004982:25455527716:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009110 [25071:25071:0419/122959.005089:25455527825:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "1204921504112226982" 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" } } [25071:25071:0419/122959.005138:25455527873:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "1204921504112226982" [25071:25071:0419/122959.005167:25455527902:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [25071:25071:0419/122959.005208:25455527943:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 31224 with a delay 1200000000, Now = 211419424 [25071:25071:0419/122959.005245:25455527979:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009130 with delay 1200000 [25071:25071:0419/122959.005297:25455528032:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [25071:25071:0419/122959.005433:25455528168:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [25071:25071:0419/122959.005472:25455528207:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 29832 with a delay 0, Now = 211419424 [25071:25071:0419/122959.005502:25455528237:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009350 with delay 0 [25071:25071:0419/122959.005548:25455528282: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 [25071:25071:0419/122959.005582:25455528323:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009350 [25071:25071:0419/122959.005659:25455528393:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009410 with delay 0 [25071:25071:0419/122959.005697:25455528432:INFO:recurring-task.cc(55)] [Retry] Scheduling 29832 with a delay 10000000, Now = 211419424 [25071:25071:0419/122959.005722:25455528457:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x602000009450 with delay 10000 [25071:25071:0419/122959.005749:25455528483:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x602000009410 [25071:25071:0419/122959.005770:25455528504:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [25071:25071:0419/122959.005810:25455528544:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000009470 with delay 0 [25071:25071:0419/122959.005837:25455528572:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x602000009470 [25071:25071:0419/122959.005873:25455528608:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [25071:25071:0419/122959.005939:25455528674:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 152360 with a delay 500000, Now = 211469424 [25071:25071:0419/122959.005971:25455528706:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x602000009490 with delay 500 [25071:25071:0419/122959.006010:25455528744:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 152232 with a delay 60000000, Now = 211469424 [25071:25071:0419/122959.006037:25455528772:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x6020000094b0 with delay 60000 [25071:25071:0419/122959.006080:25455528814:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000009490 [25071:25071:0419/122959.006106:25455528842:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122959.006149:25455528883:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122959.006173:25455528908:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [25071:25071:0419/122959.006309:25455529045: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 } } } [25071:25071:0419/122959.006387:25455529122:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122959.006426:25455529161:INFO:deterministic-scheduler.cc(33)] (Now: 211969424) Enqueuing 0x602000009550 with delay 0 [25071:25071:0419/122959.006454:25455529189:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x602000009550 [25071:25071:0419/122959.006544:25455529279: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" } } [25071:25071:0419/122959.006630:25455529365: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 [25071:25071:0419/122959.006680:25455529415:ERROR:invalidation-client-core.cc(723)] Received error message: AUTH_FAILURE, Auth error message [25071:25071:0419/122959.006801:25455529536:WARNING:invalidation-client-core.cc(753)] Issuing failure for 1 objects [25071:25071:0419/122959.007122:25455529859:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x602000009450 [ OK ] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms) [25/28] InvalidationClientImplTest.IncomingAuthErrorMessage (5 ms) [ RUN ] InvalidationClientImplTest.NetworkTimeouts [25071:25071:0419/122959.008442:25455531180:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x602000009fb0 with delay 0 [25071:25071:0419/122959.008488:25455531223:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [25071:25071:0419/122959.008741:25455531476:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a4d0 with delay 0 [25071:25071:0419/122959.008774:25455531509:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x602000009fb0 [25071:25071:0419/122959.008798:25455531533:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a4d0 [25071:25071:0419/122959.008844:25455531579:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [25071:25071:0419/122959.008898:25455531633:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a590 with delay 0 [25071:25071:0419/122959.008930:25455531665:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a590 [25071:25071:0419/122959.008957:25455531691:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [25071:25071:0419/122959.008987:25455531722:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a5d0 with delay 0 [25071:25071:0419/122959.009014:25455531748:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a5d0 [25071:25071:0419/122959.009042:25455531776:INFO:invalidation-client-core.cc(351)] Starting with no previous state [25071:25071:0419/122959.009068:25455531803:INFO:recurring-task.cc(55)] [Startup] Scheduling 180520 with a delay 0, Now = 210919424 [25071:25071:0419/122959.009098:25455531833:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a5f0 with delay 0 [25071:25071:0419/122959.009127:25455531862:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000a5f0 [25071:25071:0419/122959.009173:25455531910:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "8785589885832602037" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [25071:25071:0419/122959.009210:25455531945:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 180776 with a delay 500000, Now = 210919424 [25071:25071:0419/122959.009240:25455531975:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a610 with delay 500 [25071:25071:0419/122959.009290:25455532028:INFO:recurring-task.cc(55)] [Retry] Scheduling 180520 with a delay 60000000, Now = 210919424 [25071:25071:0419/122959.009325:25455532059:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000a630 with delay 60000 [25071:25071:0419/122959.009375:25455532110:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a610 [25071:25071:0419/122959.009405:25455532140:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122959.009456:25455532190:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122959.009585:25455532322: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: "8785589885832602037" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [25071:25071:0419/122959.009695:25455532433:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a6d0 with delay 0 [25071:25071:0419/122959.009725:25455532463:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a6d0 [25071:25071:0419/122959.009814:25455532549:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "8785589885832602037" 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" } } [25071:25071:0419/122959.009859:25455532594:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "8785589885832602037" [25071:25071:0419/122959.009885:25455532620:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [25071:25071:0419/122959.009917:25455532652:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 34568 with a delay 1200000000, Now = 211419424 [25071:25071:0419/122959.009953:25455532687:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a6f0 with delay 1200000 [25071:25071:0419/122959.009981:25455532717:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [25071:25071:0419/122959.010114:25455532850:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [25071:25071:0419/122959.010156:25455532891:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 35208 with a delay 0, Now = 211419424 [25071:25071:0419/122959.010190:25455532924:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a910 with delay 0 [25071:25071:0419/122959.010233:25455532967: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 [25071:25071:0419/122959.010280:25455533016:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a910 [25071:25071:0419/122959.010336:25455533071:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000a9d0 with delay 0 [25071:25071:0419/122959.010371:25455533106:INFO:recurring-task.cc(55)] [Retry] Scheduling 35208 with a delay 10000000, Now = 211419424 [25071:25071:0419/122959.010395:25455533130:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000aa10 with delay 10000 [25071:25071:0419/122959.010422:25455533156:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000a9d0 [25071:25071:0419/122959.010461:25455533197:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [25071:25071:0419/122959.010506:25455533240:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000aa30 with delay 0 [25071:25071:0419/122959.010534:25455533270:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000aa30 [25071:25071:0419/122959.010569:25455533304:INFO:invalidation-client-core.cc(420)] Register { source: 2 name: "oid0" }, 1 [25071:25071:0419/122959.010620:25455533369:INFO:recurring-task.cc(55)] [Send-registrations] Scheduling 180776 with a delay 500000, Now = 211469424 [25071:25071:0419/122959.010665:25455533399:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000aa50 with delay 500 [25071:25071:0419/122959.010691:25455533426:INFO:recurring-task.cc(55)] [PerformRegister] Scheduling 180648 with a delay 60000000, Now = 211469424 [25071:25071:0419/122959.010725:25455533460:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000aa70 with delay 60000 [25071:25071:0419/122959.010770:25455533504:INFO:deterministic-scheduler.cc(75)] (Now: 211969424) Running task 0x60200000aa50 [25071:25071:0419/122959.010796:25455533534:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122959.010835:25455533570:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122959.010865:25455533604:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [25071:25071:0419/122959.010990:25455533725: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 } } } [25071:25071:0419/122959.011277:25455534013:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000aa10 [25071:25071:0419/122959.012188:25455534924:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000a630 [25071:25071:0419/122959.012226:25455534960:INFO:deterministic-scheduler.cc(75)] (Now: 271469424) Running task 0x60200000aa70 [25071:25071:0419/122959.012279:25455535014: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 [25071:25071:0419/122959.012323:25455535058:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = true [25071:25071:0419/122959.012382:25455535120: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 } [25071:25071:0419/122959.012422:25455535156:INFO:recurring-task.cc(55)] [Send-info] Scheduling 180776 with a delay 500000, Now = 271469424 [25071:25071:0419/122959.012451:25455535186:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000ab10 with delay 500 [25071:25071:0419/122959.012479:25455535214:INFO:recurring-task.cc(55)] [Retry] Scheduling 180648 with a delay 60000000, Now = 271469424 [25071:25071:0419/122959.012511:25455535245:INFO:deterministic-scheduler.cc(33)] (Now: 271469424) Enqueuing 0x60200000ab30 with delay 60000 [25071:25071:0419/122959.012547:25455535280:INFO:deterministic-scheduler.cc(75)] (Now: 271969424) Running task 0x60200000ab10 [25071:25071:0419/122959.012569:25455535303:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122959.012622:25455535356:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122959.012654:25455535389:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [25071:25071:0419/122959.012792:25455535527: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 (6 ms) [26/28] InvalidationClientImplTest.NetworkTimeouts (6 ms) [ RUN ] InvalidationClientImplTest.NoRegistrationSummary [25071:25071:0419/122959.014401:25455537139:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b410 with delay 0 [25071:25071:0419/122959.014448:25455537184:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [25071:25071:0419/122959.014702:25455537438:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b930 with delay 0 [25071:25071:0419/122959.014733:25455537470:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b410 [25071:25071:0419/122959.014761:25455537495:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b930 [25071:25071:0419/122959.014814:25455537548:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [25071:25071:0419/122959.014874:25455537609:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000b9f0 with delay 0 [25071:25071:0419/122959.014907:25455537642:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000b9f0 [25071:25071:0419/122959.014929:25455537664:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [25071:25071:0419/122959.014956:25455537691:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ba30 with delay 0 [25071:25071:0419/122959.014980:25455537716:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000ba30 [25071:25071:0419/122959.015009:25455537746:INFO:invalidation-client-core.cc(351)] Starting with no previous state [25071:25071:0419/122959.015043:25455537778:INFO:recurring-task.cc(55)] [Startup] Scheduling 209448 with a delay 0, Now = 210919424 [25071:25071:0419/122959.015071:25455537806:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ba50 with delay 0 [25071:25071:0419/122959.015105:25455537843:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000ba50 [25071:25071:0419/122959.015161:25455537896:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "6533212295052816955" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [25071:25071:0419/122959.015206:25455537940:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 209704 with a delay 500000, Now = 210919424 [25071:25071:0419/122959.015231:25455537968:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ba70 with delay 500 [25071:25071:0419/122959.015258:25455538005:INFO:recurring-task.cc(55)] [Retry] Scheduling 209448 with a delay 60000000, Now = 210919424 [25071:25071:0419/122959.015298:25455538032:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ba90 with delay 60000 [25071:25071:0419/122959.015333:25455538068:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ba70 [25071:25071:0419/122959.015376:25455538111:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122959.015412:25455538147:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122959.015517:25455538252: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: "6533212295052816955" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [25071:25071:0419/122959.015630:25455538365:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000bb30 with delay 0 [25071:25071:0419/122959.015660:25455538395:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000bb30 [25071:25071:0419/122959.015762:25455538497:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "6533212295052816955" 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" } } [25071:25071:0419/122959.015807:25455538542:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "6533212295052816955" [25071:25071:0419/122959.015842:25455538577:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [25071:25071:0419/122959.015874:25455538610:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 37208 with a delay 1200000000, Now = 211419424 [25071:25071:0419/122959.015901:25455538636:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000bb50 with delay 1200000 [25071:25071:0419/122959.015950:25455538684:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [25071:25071:0419/122959.016085:25455538821:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [25071:25071:0419/122959.016121:25455538856:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 41160 with a delay 0, Now = 211419424 [25071:25071:0419/122959.016149:25455538883:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000bd70 with delay 0 [25071:25071:0419/122959.016188:25455538923: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 [25071:25071:0419/122959.016227:25455538961:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000bd70 [25071:25071:0419/122959.016296:25455539031:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000be30 with delay 0 [25071:25071:0419/122959.016336:25455539072:INFO:recurring-task.cc(55)] [Retry] Scheduling 41160 with a delay 10000000, Now = 211419424 [25071:25071:0419/122959.016365:25455539100:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000be70 with delay 10000 [25071:25071:0419/122959.016398:25455539133:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000be30 [25071:25071:0419/122959.016420:25455539155:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [25071:25071:0419/122959.016465:25455539201:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122959.016502:25455539236:INFO:deterministic-scheduler.cc(33)] (Now: 211469424) Enqueuing 0x60200000be90 with delay 0 [25071:25071:0419/122959.016530:25455539264:INFO:deterministic-scheduler.cc(75)] (Now: 211469424) Running task 0x60200000be90 [25071:25071:0419/122959.016602:25455539338: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" } } [25071:25071:0419/122959.016866:25455539601:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000be70 [25071:25071:0419/122959.017778:25455540520: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 (4 ms) [27/28] InvalidationClientImplTest.NoRegistrationSummary (4 ms) [ RUN ] InvalidationClientImplTest.Heartbeats [25071:25071:0419/122959.018449:25455541185:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000c6f0 with delay 0 [25071:25071:0419/122959.018496:25455541231:INFO:invalidation-client-core.cc(235)] Created client: Client: { client_type: 2 client_name: "clientName" }, "", <RunState 1> [25071:25071:0419/122959.018704:25455541439:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000cc10 with delay 0 [25071:25071:0419/122959.018738:25455541472:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000c6f0 [25071:25071:0419/122959.018765:25455541501:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000cc10 [25071:25071:0419/122959.018839:25455541574:INFO:invalidation-client-core.cc(286)] Starting with C++ config: { version: { major_version: 3 minor_version: 2 } smear_percent: 0 protocol_handler_config: { } } [25071:25071:0419/122959.018895:25455541630:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000ccd0 with delay 0 [25071:25071:0419/122959.018926:25455541662:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000ccd0 [25071:25071:0419/122959.018949:25455541682:WARNING:invalidation-client-core.cc(961)] Could not read state blob: [25071:25071:0419/122959.018975:25455541710:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000cd10 with delay 0 [25071:25071:0419/122959.019002:25455541737:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000cd10 [25071:25071:0419/122959.019024:25455541758:INFO:invalidation-client-core.cc(351)] Starting with no previous state [25071:25071:0419/122959.019051:25455541786:INFO:recurring-task.cc(55)] [Startup] Scheduling 231080 with a delay 0, Now = 210919424 [25071:25071:0419/122959.019081:25455541816:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000cd30 with delay 0 [25071:25071:0419/122959.019111:25455541847:INFO:deterministic-scheduler.cc(75)] (Now: 210919424) Running task 0x60200000cd30 [25071:25071:0419/122959.019176:25455541911:INFO:protocol-handler.cc(230)] Batching initialize message for client: AcquireToken, { client_type: 2 nonce: "-3310295145672353396" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } [25071:25071:0419/122959.019210:25455541946:INFO:recurring-task.cc(55)] [AcquireToken] Scheduling 231336 with a delay 500000, Now = 210919424 [25071:25071:0419/122959.019241:25455541976:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000cd50 with delay 500 [25071:25071:0419/122959.019279:25455542014:INFO:recurring-task.cc(55)] [Retry] Scheduling 231080 with a delay 60000000, Now = 210919424 [25071:25071:0419/122959.019314:25455542049:INFO:deterministic-scheduler.cc(33)] (Now: 210919424) Enqueuing 0x60200000cd70 with delay 60000 [25071:25071:0419/122959.019353:25455542088:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000cd50 [25071:25071:0419/122959.019380:25455542115:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122959.019422:25455542158:INFO:invalidation-client-core.cc(488)] Return client token = "" [25071:25071:0419/122959.019529:25455542264: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: "-3310295145672353396" application_client_id: { client_type: 2 client_name: "clientName" } digest_serialization_type: BYTE_BASED } } [25071:25071:0419/122959.019658:25455542393:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ce10 with delay 0 [25071:25071:0419/122959.019688:25455542422:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000ce10 [25071:25071:0419/122959.019782:25455542517:INFO:protocol-handler.cc(139)] Incoming message: { header: { protocol_version: { version: { major_version: 3 minor_version: 2 } } client_token: "-3310295145672353396" 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" } } [25071:25071:0419/122959.019835:25455542572:INFO:invalidation-client-core.cc(876)] Accepting server message with matching nonce: "-3310295145672353396" [25071:25071:0419/122959.019871:25455542606:INFO:invalidation-client-core.cc(591)] New token being assigned at client: "new token", Old = "" [25071:25071:0419/122959.019906:25455542643:INFO:recurring-task.cc(55)] [Heartbeat-after-new-token] Scheduling 39672 with a delay 1200000000, Now = 211419424 [25071:25071:0419/122959.019937:25455542671:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000ce30 with delay 1200000 [25071:25071:0419/122959.019966:25455542702:INFO:checking-invalidation-listener.cc(127)] Informing app that ticl is ready [25071:25071:0419/122959.020100:25455542836:INFO:invalidation-client-core.cc(943)] Ticl started: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [25071:25071:0419/122959.020142:25455542884:INFO:recurring-task.cc(55)] [Write-after-new-token] Scheduling 44808 with a delay 0, Now = 211419424 [25071:25071:0419/122959.020190:25455542924:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d050 with delay 0 [25071:25071:0419/122959.020235:25455542970: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 [25071:25071:0419/122959.020294:25455543029:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d050 [25071:25071:0419/122959.020354:25455543089:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d110 with delay 0 [25071:25071:0419/122959.020399:25455543135:INFO:recurring-task.cc(55)] [Retry] Scheduling 44808 with a delay 10000000, Now = 211419424 [25071:25071:0419/122959.020429:25455543164:INFO:deterministic-scheduler.cc(33)] (Now: 211419424) Enqueuing 0x60200000d150 with delay 10000 [25071:25071:0419/122959.020460:25455543194:INFO:deterministic-scheduler.cc(75)] (Now: 211419424) Running task 0x60200000d110 [25071:25071:0419/122959.020492:25455543226:INFO:invalidation-client-core.cc(146)] Write state completed: 1, [25071:25071:0419/122959.020745:25455543481:INFO:deterministic-scheduler.cc(75)] (Now: 221419424) Running task 0x60200000d150 [25071:25071:0419/122959.021724:25455544460:INFO:deterministic-scheduler.cc(75)] (Now: 270919424) Running task 0x60200000cd70 [25071:25071:0419/122959.042195:25455564935:INFO:deterministic-scheduler.cc(75)] (Now: 1411419424) Running task 0x60200000ce30 [25071:25071:0419/122959.042278:25455565014:INFO:invalidation-client-core.cc(179)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [25071:25071:0419/122959.042342:25455565076:INFO:invalidation-client-core.cc(190)] Sending heartbeat to server: Client: { client_type: 2 client_name: "clientName" }, "new token", <RunState 2> [25071:25071:0419/122959.042389:25455565124:INFO:invalidation-client-core.cc(888)] Sending info message to server; request server summary = false [25071:25071:0419/122959.042566:25455565302: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 } [25071:25071:0419/122959.042632:25455565367:INFO:recurring-task.cc(55)] [Send-info] Scheduling 231336 with a delay 500000, Now = 1411419424 [25071:25071:0419/122959.042674:25455565410:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000d170 with delay 500 [25071:25071:0419/122959.042706:25455565441:INFO:recurring-task.cc(55)] [Retry] Scheduling 39672 with a delay 1200000000, Now = 1411419424 [25071:25071:0419/122959.042737:25455565473:INFO:deterministic-scheduler.cc(33)] (Now: 1411419424) Enqueuing 0x60200000d190 with delay 1200000 [25071:25071:0419/122959.042777:25455565512:INFO:deterministic-scheduler.cc(75)] (Now: 1411919424) Running task 0x60200000d170 [25071:25071:0419/122959.042814:25455565549:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122959.042888:25455565622:INFO:invalidation-client-core.cc(488)] Return client token = "new token" [25071:25071:0419/122959.042915:25455565649:INFO:protocol-handler.cc(352)] Sending token on client->server message: "new token" [25071:25071:0419/122959.043144:25455565880: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 (26 ms) [28/28] InvalidationClientImplTest.Heartbeats (26 ms) SUCCESS: all tests passed. Tests took 0 seconds. 2019-04-22 01:00:08,426 - root: [DEBUG] Contents of task_output_dir: ['/b/swarming/w/ir/tmp/t/tmplF3XKE/445cdd5ff1daed10'] 2019-04-22 01:00:08,426 - root: [DEBUG] Found shard_json_files: ['/b/swarming/w/ir/tmp/t/tmplF3XKE/445cdd5ff1daed10/output.json'] 2019-04-22 01:00:08,426 - 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": "swarm2376-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1555919321790524, "id": "8915494057192899376", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux Chromium OS ASan LSan Tests (1)/32916", "builder:Linux Chromium OS ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/a6043f15f391be302c9b104d94359d54723c6d8d", "gitiles_ref:refs/heads/master", "parent_buildername:Linux Chromium OS ASan LSan Builder", "parent_buildnumber:44879", "scheduler_invocation_id:9080924119187250528", "scheduler_job_id:chromium/Linux Chromium OS ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux Chromium OS ASan LSan Tests (1)", "buildnumber": 32916, "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "got_revision_cp": "refs/heads/master@{#652813}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "chromium.memory", "parent_buildername": "Linux Chromium OS ASan LSan Builder", "parent_got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "parent_got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "parent_got_revision_cp": "refs/heads/master@{#652813}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "parent_got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "parent_got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27678}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "swarm_hashes": {"accessibility_unittests": "30691e08012156d9b1a4a61f92d6d9d7042c0530", "angle_unittests": "3468e8e17d7f4791b7848ff61a58de441a312ab8", "app_list_unittests": "10718f7035bb6b73f244bf0b2d257e9e4a078b06", "app_shell_unittests": "523dc712fe3918680886c4cbeba6ae788535a39f", "ash_unittests": "e6ef7875fb4b50c62d357f2243f97f20d4e85ed5", "aura_unittests": "84dd8b42ab683bfc38d1ece7f1810c8a25592e36", "base_unittests": "a32478c89417e8045dde4f6902bb5b54083a7ec1", "blink_common_unittests": "a6eadda574f2f72d9bc771634cddbfe9fd1b9400", "blink_fuzzer_unittests": "e88db7944eec25713d967eb94f51daea7fdae2f0", "blink_heap_unittests": "454088795a253b039f34e348fc9a97521214c998", "blink_platform_unittests": "5322b95e243fe267b6e7c9421c37aac746fdd9af", "blink_unittests": "795ddfa50b66a6d218a56cac88e28f0302f37cde", "boringssl_crypto_tests": "c2f334da5178ba2ca3904540296c350482cf81d0", "boringssl_ssl_tests": "1272e9547f075b3f49631b2c5f8461fcd92fcc7a", "browser_tests": "6a6c66f7add80c520d7bb070016769220c2b78c6", "cacheinvalidation_unittests": "c2867b5786c4d50cf798088a562927240780f261", "capture_unittests": "aaca36a72085818fcbe3ebe0679da956629c3322", "cast_unittests": "66a0beebe1f96157e6d60397fc8c653e9ca3be7c", "cc_unittests": "a9d2debdce4f1c7b74fd1f468b68878a45758616", "chrome_app_unittests": "23f30377a2e93f7a34bc48f922774fe27e8ed62d", "chromedriver_unittests": "cebbd7e8aa576165555a541ba9a3b13b9ceb69d7", "chromeos_components_unittests": "178e3b882fd8f2a613e3a54334f5edd9cef1e460", "chromeos_unittests": "f2d23cc501c84553da82f66b0520c1e6e87ead53", "components_browsertests": "da6444e3f33f8f45534e6a61c5f11dad75ecc857", "components_unittests": "7509985a5dce24f0d0e00061f0fd4c17a5b836af", "compositor_unittests": "979c2a5deb3d75186443823aab31a5df38efb356", "content_browsertests": "fe13b470ff7f61d88321be3d1352d4c5bc593ed8", "content_unittests": "b27eed502e07c9003cc28611cbd4ab41a9a6283f", "crypto_unittests": "7f61e87da65c17ca8ad64c030b77f531c3efa9e9", "dbus_unittests": "c92afac4c7ee545556fc9633efc8bf57fcad4c0f", "device_unittests": "637142f5ecbeec7288373708f7c96c433062bff0", "display_unittests": "fa93a48ab72352eb316272e8cd174d2ab5daea7b", "events_unittests": "3fb3632f4f1e97993548ed398a213d93066eff89", "exo_unittests": "b7588c9bd7bc85ac7e3b62f04ddd8014c299846c", "extensions_browsertests": "c6b1be7127b5523d2e3a846b0093fad694955bd9", "extensions_unittests": "85f05c3682b5cbd499cd2c43053f3738ab305fde", "filesystem_service_unittests": "388d408d7357ee4166a1a8bd7480caccfda0e63f", "gcm_unit_tests": "94a80d7fb19feb2cbff0dac3213f287869a6830c", "gfx_unittests": "d8b1d49cb6018e4dea0b3020e54b734e737b8a1b", "gl_unittests_ozone": "087c2b16bd05e1c45eaffbfbb0063919ed0aa76c", "google_apis_unittests": "dbd965bd8a1a1c582ff3bbc165aaa5eaa12cb838", "gpu_unittests": "bdbb72f43db921b4a9703d31d85472f573f6f758", "interactive_ui_tests": "cf7f5c9d2c2385e346986262f23cb063c2e7ffd3", "ipc_tests": "2d462d862a879c18e72311eba43bafeb6a5aac60", "jingle_unittests": "93a4aabbaa184c2ab67030f6b65d3d41730c39ff", "keyboard_unittests": "7a8a3a6a7156261a3dbea0bdade9492d86c37334", "latency_unittests": "6c38a2ea796bb761a98c108917e7d2f03e364af7", "leveldb_service_unittests": "49412188bc723d8fec4bd49bca4b150b6327250b", "libjingle_xmpp_unittests": "191c536f10d4a088bea5cfe5ec8b8d4780b8f9ae", "media_blink_unittests": "8cfb49d6085fadfa0d752b37faf4c8b78f0fb0b1", "media_service_unittests": "789fbb2cfcd4f6d68ba40474a48c5828b3e58ad4", "media_unittests": "61aea81b826c21c4418e6831fd35c05aceb43a1a", "message_center_unittests": "e2369ca8656dc3495353ad5f6c8883d1fc52114b", "midi_unittests": "3ac38c78dbc5cce75d2753f2169a0b16699ac1ac", "mojo_core_unittests": "23b1dd3c99a86e73f5a2d014aed64b71ea1f5159", "mojo_unittests": "9c62fba34390e76f027c408bf231884b7b3cfb54", "nacl_helper_nonsfi_unittests": "03d6a9a9906d64afa55b7427a602b35dd43034c2", "nacl_loader_unittests": "7112b0bff15b2d4a57867a9310f96d5975d87ebb", "native_theme_unittests": "e51973dba9a60dd016baa0caa84853a1d8141aa9", "net_unittests": "b3a5aab1d5d2b7f68bfce33989c6c55c4ab6583b", "ozone_gl_unittests": "6cce07f7d3a2687770f46aed7dc257d9c84fc3d8", "ozone_unittests": "8fe310399f4d3d4e3aea4e475cda7c4ec90bf53d", "ozone_x11_unittests": "1de4ce9a0eda735d0b8ee87b4cfa451fea47df67", "pdf_unittests": "c7d89d8b63918b0821bfbaa4a7bc95a9e95e68a2", "perfetto_unittests": "ecc4f566d8ae270faec55c02913de14eb319249e", "ppapi_unittests": "04aea971086845ae07592c05cb8515e7a19e076c", "printing_unittests": "1dfbec3b3d4dfdc617d2c39426fbb1dfe9dc46d0", "remoting_unittests": "1aa0f16f5303276102a00db5dc93f6e9e8f722ba", "sandbox_linux_unittests": "3582bbcd401d61ae91eea0053187785aece4822f", "service_manager_unittests": "c53df1939451cc9756ad35771b8c0b1f8ce49573", "services_unittests": "a21571a6d0f9904fd2444cb5617e58a85f1d3aa1", "shell_dialogs_unittests": "5b5fa37dad02a0d85c1c721fbaee986ce3444146", "skia_unittests": "e531702a972bdb4caaab0e20be57008da1067286", "snapshot_unittests": "b7a2d9bdffd18e54ff415c41a3da760774cfeacd", "sql_unittests": "a3d87c57d727cf9632ef610c3b86a201e48a0299", "storage_unittests": "fab5ff952e2bac33bfd4d3523bc6f547203025d1", "sync_integration_tests": "0385b60a931ed8734024d5ea029d794385524667", "traffic_annotation_auditor_unittests": "c67d9fe11e5a566302bca9a12130e4c741c8d284", "ui_base_unittests": "7873d9abebc42853e122035d4cc040a6a73ea644", "ui_chromeos_unittests": "f8ed2198ecdf741bc71dab6d71ac413df304a73f", "ui_touch_selection_unittests": "59e67da78e3fcc3ccce02e26d2c8e1b359635655", "unit_tests": "2874a7bbbd2f9889e64df2b1de973d54668479c1", "url_unittests": "fbb72e9f6309a097aeee9673be870833f6a44dab", "usage_time_limit_unittests": "f13edfc7eb9d5fb6f423a6e832f8f39cdc61d1f3", "views_unittests": "57dc91f1b782e443b5f060832ff12151a571c421", "viz_unittests": "2c4a581d32da18c0a23cfffd3def28604d6fadce", "wayland_client_perftests": "48e5b8c88f6816cef63f35c93f1ba015ce9776db", "wm_unittests": "0b26de8b3f70a0fbe117dd1e9a2f50d9e33f6c3e", "wtf_unittests": "682a8a015226b1fd4bf425e0db497d0aca797629"}} --summary-json /b/swarming/w/ir/tmp/t/tmpKpgOAF.json --task-output-dir /b/swarming/w/ir/tmp/t/tmplF3XKE -o /b/swarming/w/ir/tmp/t/tmpjTzCCj.json /b/swarming/w/ir/tmp/t/tmplF3XKE/445cdd5ff1daed10/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": "swarm2376-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1555919321790524, "id": "8915494057192899376", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux Chromium OS ASan LSan Tests (1)/32916", "builder:Linux Chromium OS ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/a6043f15f391be302c9b104d94359d54723c6d8d", "gitiles_ref:refs/heads/master", "parent_buildername:Linux Chromium OS ASan LSan Builder", "parent_buildnumber:44879", "scheduler_invocation_id:9080924119187250528", "scheduler_job_id:chromium/Linux Chromium OS ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux Chromium OS ASan LSan Tests (1)", "buildnumber": 32916, "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "got_revision_cp": "refs/heads/master@{#652813}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "chromium.memory", "parent_buildername": "Linux Chromium OS ASan LSan Builder", "parent_got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "parent_got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "parent_got_revision_cp": "refs/heads/master@{#652813}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "parent_got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "parent_got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27678}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "swarm_hashes": {"accessibility_unittests": "30691e08012156d9b1a4a61f92d6d9d7042c0530", "angle_unittests": "3468e8e17d7f4791b7848ff61a58de441a312ab8", "app_list_unittests": "10718f7035bb6b73f244bf0b2d257e9e4a078b06", "app_shell_unittests": "523dc712fe3918680886c4cbeba6ae788535a39f", "ash_unittests": "e6ef7875fb4b50c62d357f2243f97f20d4e85ed5", "aura_unittests": "84dd8b42ab683bfc38d1ece7f1810c8a25592e36", "base_unittests": "a32478c89417e8045dde4f6902bb5b54083a7ec1", "blink_common_unittests": "a6eadda574f2f72d9bc771634cddbfe9fd1b9400", "blink_fuzzer_unittests": "e88db7944eec25713d967eb94f51daea7fdae2f0", "blink_heap_unittests": "454088795a253b039f34e348fc9a97521214c998", "blink_platform_unittests": "5322b95e243fe267b6e7c9421c37aac746fdd9af", "blink_unittests": "795ddfa50b66a6d218a56cac88e28f0302f37cde", "boringssl_crypto_tests": "c2f334da5178ba2ca3904540296c350482cf81d0", "boringssl_ssl_tests": "1272e9547f075b3f49631b2c5f8461fcd92fcc7a", "browser_tests": "6a6c66f7add80c520d7bb070016769220c2b78c6", "cacheinvalidation_unittests": "c2867b5786c4d50cf798088a562927240780f261", "capture_unittests": "aaca36a72085818fcbe3ebe0679da956629c3322", "cast_unittests": "66a0beebe1f96157e6d60397fc8c653e9ca3be7c", "cc_unittests": "a9d2debdce4f1c7b74fd1f468b68878a45758616", "chrome_app_unittests": "23f30377a2e93f7a34bc48f922774fe27e8ed62d", "chromedriver_unittests": "cebbd7e8aa576165555a541ba9a3b13b9ceb69d7", "chromeos_components_unittests": "178e3b882fd8f2a613e3a54334f5edd9cef1e460", "chromeos_unittests": "f2d23cc501c84553da82f66b0520c1e6e87ead53", "components_browsertests": "da6444e3f33f8f45534e6a61c5f11dad75ecc857", "components_unittests": "7509985a5dce24f0d0e00061f0fd4c17a5b836af", "compositor_unittests": "979c2a5deb3d75186443823aab31a5df38efb356", "content_browsertests": "fe13b470ff7f61d88321be3d1352d4c5bc593ed8", "content_unittests": "b27eed502e07c9003cc28611cbd4ab41a9a6283f", "crypto_unittests": "7f61e87da65c17ca8ad64c030b77f531c3efa9e9", "dbus_unittests": "c92afac4c7ee545556fc9633efc8bf57fcad4c0f", "device_unittests": "637142f5ecbeec7288373708f7c96c433062bff0", "display_unittests": "fa93a48ab72352eb316272e8cd174d2ab5daea7b", "events_unittests": "3fb3632f4f1e97993548ed398a213d93066eff89", "exo_unittests": "b7588c9bd7bc85ac7e3b62f04ddd8014c299846c", "extensions_browsertests": "c6b1be7127b5523d2e3a846b0093fad694955bd9", "extensions_unittests": "85f05c3682b5cbd499cd2c43053f3738ab305fde", "filesystem_service_unittests": "388d408d7357ee4166a1a8bd7480caccfda0e63f", "gcm_unit_tests": "94a80d7fb19feb2cbff0dac3213f287869a6830c", "gfx_unittests": "d8b1d49cb6018e4dea0b3020e54b734e737b8a1b", "gl_unittests_ozone": "087c2b16bd05e1c45eaffbfbb0063919ed0aa76c", "google_apis_unittests": "dbd965bd8a1a1c582ff3bbc165aaa5eaa12cb838", "gpu_unittests": "bdbb72f43db921b4a9703d31d85472f573f6f758", "interactive_ui_tests": "cf7f5c9d2c2385e346986262f23cb063c2e7ffd3", "ipc_tests": "2d462d862a879c18e72311eba43bafeb6a5aac60", "jingle_unittests": "93a4aabbaa184c2ab67030f6b65d3d41730c39ff", "keyboard_unittests": "7a8a3a6a7156261a3dbea0bdade9492d86c37334", "latency_unittests": "6c38a2ea796bb761a98c108917e7d2f03e364af7", "leveldb_service_unittests": "49412188bc723d8fec4bd49bca4b150b6327250b", "libjingle_xmpp_unittests": "191c536f10d4a088bea5cfe5ec8b8d4780b8f9ae", "media_blink_unittests": "8cfb49d6085fadfa0d752b37faf4c8b78f0fb0b1", "media_service_unittests": "789fbb2cfcd4f6d68ba40474a48c5828b3e58ad4", "media_unittests": "61aea81b826c21c4418e6831fd35c05aceb43a1a", "message_center_unittests": "e2369ca8656dc3495353ad5f6c8883d1fc52114b", "midi_unittests": "3ac38c78dbc5cce75d2753f2169a0b16699ac1ac", "mojo_core_unittests": "23b1dd3c99a86e73f5a2d014aed64b71ea1f5159", "mojo_unittests": "9c62fba34390e76f027c408bf231884b7b3cfb54", "nacl_helper_nonsfi_unittests": "03d6a9a9906d64afa55b7427a602b35dd43034c2", "nacl_loader_unittests": "7112b0bff15b2d4a57867a9310f96d5975d87ebb", "native_theme_unittests": "e51973dba9a60dd016baa0caa84853a1d8141aa9", "net_unittests": "b3a5aab1d5d2b7f68bfce33989c6c55c4ab6583b", "ozone_gl_unittests": "6cce07f7d3a2687770f46aed7dc257d9c84fc3d8", "ozone_unittests": "8fe310399f4d3d4e3aea4e475cda7c4ec90bf53d", "ozone_x11_unittests": "1de4ce9a0eda735d0b8ee87b4cfa451fea47df67", "pdf_unittests": "c7d89d8b63918b0821bfbaa4a7bc95a9e95e68a2", "perfetto_unittests": "ecc4f566d8ae270faec55c02913de14eb319249e", "ppapi_unittests": "04aea971086845ae07592c05cb8515e7a19e076c", "printing_unittests": "1dfbec3b3d4dfdc617d2c39426fbb1dfe9dc46d0", "remoting_unittests": "1aa0f16f5303276102a00db5dc93f6e9e8f722ba", "sandbox_linux_unittests": "3582bbcd401d61ae91eea0053187785aece4822f", "service_manager_unittests": "c53df1939451cc9756ad35771b8c0b1f8ce49573", "services_unittests": "a21571a6d0f9904fd2444cb5617e58a85f1d3aa1", "shell_dialogs_unittests": "5b5fa37dad02a0d85c1c721fbaee986ce3444146", "skia_unittests": "e531702a972bdb4caaab0e20be57008da1067286", "snapshot_unittests": "b7a2d9bdffd18e54ff415c41a3da760774cfeacd", "sql_unittests": "a3d87c57d727cf9632ef610c3b86a201e48a0299", "storage_unittests": "fab5ff952e2bac33bfd4d3523bc6f547203025d1", "sync_integration_tests": "0385b60a931ed8734024d5ea029d794385524667", "traffic_annotation_auditor_unittests": "c67d9fe11e5a566302bca9a12130e4c741c8d284", "ui_base_unittests": "7873d9abebc42853e122035d4cc040a6a73ea644", "ui_chromeos_unittests": "f8ed2198ecdf741bc71dab6d71ac413df304a73f", "ui_touch_selection_unittests": "59e67da78e3fcc3ccce02e26d2c8e1b359635655", "unit_tests": "2874a7bbbd2f9889e64df2b1de973d54668479c1", "url_unittests": "fbb72e9f6309a097aeee9673be870833f6a44dab", "usage_time_limit_unittests": "f13edfc7eb9d5fb6f423a6e832f8f39cdc61d1f3", "views_unittests": "57dc91f1b782e443b5f060832ff12151a571c421", "viz_unittests": "2c4a581d32da18c0a23cfffd3def28604d6fadce", "wayland_client_perftests": "48e5b8c88f6816cef63f35c93f1ba015ce9776db", "wm_unittests": "0b26de8b3f70a0fbe117dd1e9a2f50d9e33f6c3e", "wtf_unittests": "682a8a015226b1fd4bf425e0db497d0aca797629"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpKpgOAF.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmplF3XKE', '-o', '/b/swarming/w/ir/tmp/t/tmpjTzCCj.json', '/b/swarming/w/ir/tmp/t/tmplF3XKE/445cdd5ff1daed10/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": "swarm2376-c4", "buildbucket": {"build": {"bucket": "luci.chromium.ci", "created_by": "project:chromium", "created_ts": 1555919321790524, "id": "8915494057192899376", "project": "chromium", "tags": ["build_address:luci.chromium.ci/Linux Chromium OS ASan LSan Tests (1)/32916", "builder:Linux Chromium OS ASan LSan Tests (1)", "buildset:commit/gitiles/chromium.googlesource.com/chromium/src/+/a6043f15f391be302c9b104d94359d54723c6d8d", "gitiles_ref:refs/heads/master", "parent_buildername:Linux Chromium OS ASan LSan Builder", "parent_buildnumber:44879", "scheduler_invocation_id:9080924119187250528", "scheduler_job_id:chromium/Linux Chromium OS ASan LSan Tests (1)", "user_agent:luci-scheduler", "user_agent:recipe"]}, "hostname": "cr-buildbucket.appspot.com"}, "buildername": "Linux Chromium OS ASan LSan Tests (1)", "buildnumber": 32916, "got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "got_revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "got_revision_cp": "refs/heads/master@{#652813}", "got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "got_webrtc_revision_cp": "refs/heads/master@{#27678}", "mastername": "chromium.memory", "parent_buildername": "Linux Chromium OS ASan LSan Builder", "parent_got_angle_revision": "c467f7b5418856515b9f321495def98ee8ad0554", "parent_got_dawn_revision": "22cee9ae36b23a8908525d668ef4728a26c931c4", "parent_got_nacl_revision": "6abc006f6760ec49350cd45e8bccbff4809725ac", "parent_got_revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "parent_got_revision_cp": "refs/heads/master@{#652813}", "parent_got_swarming_client_revision": "aa60736aded9fc32a0e21a81f5fc51f6009d01f3", "parent_got_v8_revision": "49d1e6f9b11ed9a1a2e7b6855ae26907ec119713", "parent_got_v8_revision_cp": "refs/heads/7.6.1@{#1}", "parent_got_webrtc_revision": "852bffb6063aa36814c89a58390581e59643f1fb", "parent_got_webrtc_revision_cp": "refs/heads/master@{#27678}", "parent_mastername": "chromium.memory", "path_config": "generic", "recipe": "chromium", "revision": "a6043f15f391be302c9b104d94359d54723c6d8d", "swarm_hashes": {"accessibility_unittests": "30691e08012156d9b1a4a61f92d6d9d7042c0530", "angle_unittests": "3468e8e17d7f4791b7848ff61a58de441a312ab8", "app_list_unittests": "10718f7035bb6b73f244bf0b2d257e9e4a078b06", "app_shell_unittests": "523dc712fe3918680886c4cbeba6ae788535a39f", "ash_unittests": "e6ef7875fb4b50c62d357f2243f97f20d4e85ed5", "aura_unittests": "84dd8b42ab683bfc38d1ece7f1810c8a25592e36", "base_unittests": "a32478c89417e8045dde4f6902bb5b54083a7ec1", "blink_common_unittests": "a6eadda574f2f72d9bc771634cddbfe9fd1b9400", "blink_fuzzer_unittests": "e88db7944eec25713d967eb94f51daea7fdae2f0", "blink_heap_unittests": "454088795a253b039f34e348fc9a97521214c998", "blink_platform_unittests": "5322b95e243fe267b6e7c9421c37aac746fdd9af", "blink_unittests": "795ddfa50b66a6d218a56cac88e28f0302f37cde", "boringssl_crypto_tests": "c2f334da5178ba2ca3904540296c350482cf81d0", "boringssl_ssl_tests": "1272e9547f075b3f49631b2c5f8461fcd92fcc7a", "browser_tests": "6a6c66f7add80c520d7bb070016769220c2b78c6", "cacheinvalidation_unittests": "c2867b5786c4d50cf798088a562927240780f261", "capture_unittests": "aaca36a72085818fcbe3ebe0679da956629c3322", "cast_unittests": "66a0beebe1f96157e6d60397fc8c653e9ca3be7c", "cc_unittests": "a9d2debdce4f1c7b74fd1f468b68878a45758616", "chrome_app_unittests": "23f30377a2e93f7a34bc48f922774fe27e8ed62d", "chromedriver_unittests": "cebbd7e8aa576165555a541ba9a3b13b9ceb69d7", "chromeos_components_unittests": "178e3b882fd8f2a613e3a54334f5edd9cef1e460", "chromeos_unittests": "f2d23cc501c84553da82f66b0520c1e6e87ead53", "components_browsertests": "da6444e3f33f8f45534e6a61c5f11dad75ecc857", "components_unittests": "7509985a5dce24f0d0e00061f0fd4c17a5b836af", "compositor_unittests": "979c2a5deb3d75186443823aab31a5df38efb356", "content_browsertests": "fe13b470ff7f61d88321be3d1352d4c5bc593ed8", "content_unittests": "b27eed502e07c9003cc28611cbd4ab41a9a6283f", "crypto_unittests": "7f61e87da65c17ca8ad64c030b77f531c3efa9e9", "dbus_unittests": "c92afac4c7ee545556fc9633efc8bf57fcad4c0f", "device_unittests": "637142f5ecbeec7288373708f7c96c433062bff0", "display_unittests": "fa93a48ab72352eb316272e8cd174d2ab5daea7b", "events_unittests": "3fb3632f4f1e97993548ed398a213d93066eff89", "exo_unittests": "b7588c9bd7bc85ac7e3b62f04ddd8014c299846c", "extensions_browsertests": "c6b1be7127b5523d2e3a846b0093fad694955bd9", "extensions_unittests": "85f05c3682b5cbd499cd2c43053f3738ab305fde", "filesystem_service_unittests": "388d408d7357ee4166a1a8bd7480caccfda0e63f", "gcm_unit_tests": "94a80d7fb19feb2cbff0dac3213f287869a6830c", "gfx_unittests": "d8b1d49cb6018e4dea0b3020e54b734e737b8a1b", "gl_unittests_ozone": "087c2b16bd05e1c45eaffbfbb0063919ed0aa76c", "google_apis_unittests": "dbd965bd8a1a1c582ff3bbc165aaa5eaa12cb838", "gpu_unittests": "bdbb72f43db921b4a9703d31d85472f573f6f758", "interactive_ui_tests": "cf7f5c9d2c2385e346986262f23cb063c2e7ffd3", "ipc_tests": "2d462d862a879c18e72311eba43bafeb6a5aac60", "jingle_unittests": "93a4aabbaa184c2ab67030f6b65d3d41730c39ff", "keyboard_unittests": "7a8a3a6a7156261a3dbea0bdade9492d86c37334", "latency_unittests": "6c38a2ea796bb761a98c108917e7d2f03e364af7", "leveldb_service_unittests": "49412188bc723d8fec4bd49bca4b150b6327250b", "libjingle_xmpp_unittests": "191c536f10d4a088bea5cfe5ec8b8d4780b8f9ae", "media_blink_unittests": "8cfb49d6085fadfa0d752b37faf4c8b78f0fb0b1", "media_service_unittests": "789fbb2cfcd4f6d68ba40474a48c5828b3e58ad4", "media_unittests": "61aea81b826c21c4418e6831fd35c05aceb43a1a", "message_center_unittests": "e2369ca8656dc3495353ad5f6c8883d1fc52114b", "midi_unittests": "3ac38c78dbc5cce75d2753f2169a0b16699ac1ac", "mojo_core_unittests": "23b1dd3c99a86e73f5a2d014aed64b71ea1f5159", "mojo_unittests": "9c62fba34390e76f027c408bf231884b7b3cfb54", "nacl_helper_nonsfi_unittests": "03d6a9a9906d64afa55b7427a602b35dd43034c2", "nacl_loader_unittests": "7112b0bff15b2d4a57867a9310f96d5975d87ebb", "native_theme_unittests": "e51973dba9a60dd016baa0caa84853a1d8141aa9", "net_unittests": "b3a5aab1d5d2b7f68bfce33989c6c55c4ab6583b", "ozone_gl_unittests": "6cce07f7d3a2687770f46aed7dc257d9c84fc3d8", "ozone_unittests": "8fe310399f4d3d4e3aea4e475cda7c4ec90bf53d", "ozone_x11_unittests": "1de4ce9a0eda735d0b8ee87b4cfa451fea47df67", "pdf_unittests": "c7d89d8b63918b0821bfbaa4a7bc95a9e95e68a2", "perfetto_unittests": "ecc4f566d8ae270faec55c02913de14eb319249e", "ppapi_unittests": "04aea971086845ae07592c05cb8515e7a19e076c", "printing_unittests": "1dfbec3b3d4dfdc617d2c39426fbb1dfe9dc46d0", "remoting_unittests": "1aa0f16f5303276102a00db5dc93f6e9e8f722ba", "sandbox_linux_unittests": "3582bbcd401d61ae91eea0053187785aece4822f", "service_manager_unittests": "c53df1939451cc9756ad35771b8c0b1f8ce49573", "services_unittests": "a21571a6d0f9904fd2444cb5617e58a85f1d3aa1", "shell_dialogs_unittests": "5b5fa37dad02a0d85c1c721fbaee986ce3444146", "skia_unittests": "e531702a972bdb4caaab0e20be57008da1067286", "snapshot_unittests": "b7a2d9bdffd18e54ff415c41a3da760774cfeacd", "sql_unittests": "a3d87c57d727cf9632ef610c3b86a201e48a0299", "storage_unittests": "fab5ff952e2bac33bfd4d3523bc6f547203025d1", "sync_integration_tests": "0385b60a931ed8734024d5ea029d794385524667", "traffic_annotation_auditor_unittests": "c67d9fe11e5a566302bca9a12130e4c741c8d284", "ui_base_unittests": "7873d9abebc42853e122035d4cc040a6a73ea644", "ui_chromeos_unittests": "f8ed2198ecdf741bc71dab6d71ac413df304a73f", "ui_touch_selection_unittests": "59e67da78e3fcc3ccce02e26d2c8e1b359635655", "unit_tests": "2874a7bbbd2f9889e64df2b1de973d54668479c1", "url_unittests": "fbb72e9f6309a097aeee9673be870833f6a44dab", "usage_time_limit_unittests": "f13edfc7eb9d5fb6f423a6e832f8f39cdc61d1f3", "views_unittests": "57dc91f1b782e443b5f060832ff12151a571c421", "viz_unittests": "2c4a581d32da18c0a23cfffd3def28604d6fadce", "wayland_client_perftests": "48e5b8c88f6816cef63f35c93f1ba015ce9776db", "wm_unittests": "0b26de8b3f70a0fbe117dd1e9a2f50d9e33f6c3e", "wtf_unittests": "682a8a015226b1fd4bf425e0db497d0aca797629"}}', '--summary-json', '/b/swarming/w/ir/tmp/t/tmpKpgOAF.json', '--task-output-dir', '/b/swarming/w/ir/tmp/t/tmplF3XKE', '-o', '/b/swarming/w/ir/tmp/t/tmpjTzCCj.json', '/b/swarming/w/ir/tmp/t/tmplF3XKE/445cdd5ff1daed10/output.json'] returned exit code 0